openHAB 2.0 binding

[undee]

The binding doesn't seem to handle the "requestTime" function yet. Time-aware sensors would be able to handle temporary OpenHAB outages by executing some scheduled actions autonomously, which I could use in the window cover controllers I'm developing.

[kolaf]

@TimO Thanks for the update. Unfortunately it did not seem to change anything for me, rfxcom still fails trying to use the wrong lock file. If it is helpful I can send you the log. Appreciate your input and effort.

[kolaf]

The weird thing is that it seems to work with an older version of OH2 (and an old version of your binding), but not with the more recent beta releases.

[TimO]

@kolaf : My guess is, the implementation in the could be the problem. Please do a litte test: remove the mysensors.jar file from the addons folder. Start OH2. RFXCOM should start fine now. Copy the mysensors.jar in the addons folder. OH2 will try to load the binding. What is the result?

I suppose this way both binding work fine together?!

[kolaf]

@TimO I tried this before, and removing the MySensors binding made the rfxcom binding work. However, this was not the case this time. I will try a bit later to also remove the zwave binding.

20:56:34.098 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:43b9314d' changed from UNINITIALIZED to INITIALIZING
20:56:34.115 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
20:56:34.115 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:43b9314d' changed from INITIALIZING to ONLINE
RXTX Warning:  Removing stale lock file. /var/lock/LCK..ttyACM0
20:56:34.361 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is     initialized
20:56:34.384 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave     controller
20:56:34.385 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to     5000ms. Soft reset is false.
20:56:34.419 [INFO ] [me.event.ThingStatusInfoChangedEvent] -     'zwave:serial_zstick:43b9314d' changed from ONLINE to     INITIALIZING
20:56:34.444 [INFO ] [smarthome.event.InboxUpdatedEvent   ] - Discovery Result     with UID     'sonos:zoneplayer:RINCON_5CAAFD2BB4D801400' has been updated.
20:56:34.578 [INFO ] [smarthome.event.InboxUpdatedEvent   ] - Discovery Result     with UID     'sonos:zoneplayer:RINCON_5CAAFD21C16201400' has been updated.
20:56:34.756 [INFO ] [smarthome.event.InboxUpdatedEvent   ] - Discovery Result     with UID     'sonos:zoneplayer:RINCON_5CAAFD2BB4FE01400' has been updated.
20:56:34.852 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
20:56:34.866 [INFO ] [smarthome.event.InboxUpdatedEvent   ] - Discovery Result with UID 'hue:bridge:0017881c7280' has been     updated.
20:56:34.869 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
20:56:34.998 [INFO ] [.openhab.core.internal.CoreActivator] - openHAB runtime has been started (v2.0.0, build 201602200203).
20:56:35.015 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.sitemap'
20:56:35.444 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mysensors.things'
20:56:35.491 [INFO ] [smarthome.event.ThingAddedEvent     ] - Thing 'mysensors:bridge-ser:gateway' has been added.
20:56:35.500 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:bridge-ser:gateway' changed from UNINITIALIZED to     INITIALIZING
RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyACM0: File exists. It is mine

�a�� testRead() Lock file failed
RXTX Warning:  Removing stale lock file. /var/lock/LCK..mysensorsUSB
20:56:37.420 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 37: Not initialized yet, ignoring message.
20:56:37.426 [ERROR] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (CAN), resending
20:56:37.427 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 37: Not initialized yet, ignoring message.
20:56:37.429 [WARN ] [ssage.ApplicationCommandMessageClass] - NODE 37: Not initialized yet, ignoring message.
20:56:38.773 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:bridge-ser:gateway' changed from INITIALIZING to ONLINE
20:56:38.774 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rfxcom.things'
20:56:38.780 [INFO ] [smarthome.event.ThingAddedEvent     ] - Thing 'rfxcom:bridge:rfxtrx' has been added.
20:56:38.790 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'rfxcom:bridge:rfxtrx' changed from UNINITIALIZED to INITIALIZING
20:56:38.792 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'rfxcom:bridge:rfxtrx' changed from INITIALIZING to OFFLINE
RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..mysensorsUSB: File exists. It is mine

�`�� testRead() Lock file failed
20:56:38.805 [ERROR] [g.rfxcom.handler.RFXComBridgeHandler] - Connection to RFXCOM transceiver failed: null

[kolaf]

It appears that I get these errors even if I remove all the offending bindings. I think I need to start with a completely clean installation and see how it goes. I will let you know.

[kolaf]

Success, I think.

I started a brand-new installation of the latest OH2 snapshot, and sequentially added the rfxcom, z-wave, and mysensors bindings. After fiddling a bit with getting serial ports recognised by OH2 and getting the permissions correct, it seems to work. I still get some weird error messages, but apparently the library is able to work through its issues :-). An example of what I mean is included.

08:30:03.894 [INFO ] [smarthome.event.ThingAddedEvent     ] - Thing 'mysensors:bridge-ser:334037be' has been added.
08:30:03.910 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:bridge-ser:334037be' changed from UNINITIALIZED to INITIALIZING
RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..rfxtrxUSB: File exists. It is mine

@�2� testRead() Lock file failed
RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyACM0: File exists. It is mine

@�2� testRead() Lock file failed
08:30:04.043 [INFO ] [smarthome.event.ItemAddedEvent      ] - Item 'mysensors_bridge_ser_334037be' has been added.
08:30:04.219 [INFO ] [rthome.event.ItemThingLinkAddedEvent] - Link 'mysensors_bridge_ser_334037be-mysensors:bridge-ser:334037be' has been added.
08:30:07.060 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:bridge-ser:334037be' changed from INITIALIZING to ONLINE

[kolaf]

Returns out that I am still seeing the problem sometimes. If I change the configuration so that the bindings are reloaded (especially the zwav binding) it fails to reconnect to the serial port. I found someone who had posted an updated serial binding which supposedly solved some related problem (I think), but I'm not sure. It does not appear to have had any effect on the problem.

The modified version is available from one of the last posts here: https://github.com/openhab/openhab2-addons/issues/671

[kolaf]

I managed to get things working pretty well under Linux, but I have now switched to a Windows-based installation to see how that is.

Currently I have all three bindings working at the same time using three different serial ports. This is finally allowed me to pay attention to what the mysensors binding is doing.

The seems to be some kind of delay through the system for messages coming from the device. This is quite evident from the log included below. Device number three is a power sensor which transmits about once a minute. For some reason things are bunched together. I guess some of these could be Retransmissions, though. The sensor is located 4 m away from the gateway. Number 10 is a temperature sensor in the basement.

For some reason I have had severe problems getting the sensor to talk to the Gateway today. It shouldn't be related to the binding, I know, but I'm loosing my mind trying to keep track of all the different factors here.

2016-04-10 16:56:19.535 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 10;1;1;0;0;6.3
2016-04-10 16:56:20.512 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 10;1;1;0;0;6.3
2016-04-10 16:56:21.747 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 10;1;1;0;0;6.3
2016-04-10 16:56:21.805 [INFO ] [marthome.event.ItemStateChangedEvent] - FirstFloorHallMotionSensor changed from ON to OFF
2016-04-10 16:56:21.805 [INFO ] [marthome.event.ItemStateChangedEvent] - rfxcom_lighting2_A1WJD2HB_15669958_10_command changed from ON to OFF
2016-04-10 16:56:21.806 [INFO ] [marthome.event.ItemStateChangedEvent] - rfxcom_lighting2_A1WJD2HB_15669958_10_dimmingLevel changed from 100 to 0
2016-04-10 16:56:21.807 [INFO ] [marthome.event.ItemStateChangedEvent] - rfxcom_lighting2_A1WJD2HB_15669958_10_contact changed from OPEN to CLOSED
2016-04-10 16:56:24.922 [INFO ] [marthome.event.ItemStateChangedEvent] - FirstFloorHallMotionSensor changed from OFF to ON
2016-04-10 16:56:24.923 [INFO ] [marthome.event.ItemStateChangedEvent] - rfxcom_lighting2_A1WJD2HB_15669958_10_command changed from OFF to ON
2016-04-10 16:56:24.924 [INFO ] [marthome.event.ItemStateChangedEvent] - rfxcom_lighting2_A1WJD2HB_15669958_10_dimmingLevel changed from 0 to 100
2016-04-10 16:56:24.926 [INFO ] [marthome.event.ItemStateChangedEvent] - rfxcom_lighting2_A1WJD2HB_15669958_10_contact changed from CLOSED to OPEN
2016-04-10 16:56:55.048 [INFO ] [marthome.event.ItemStateChangedEvent] - CurrentDate changed from 2016-04-10T16:55:55.046+0200 to 2016-04-10T16:56:55.045+0200
2016-04-10 16:56:55.049 [INFO ] [ome.event.GroupItemStateChangedEvent] - ntp_ntp_local changed from 2016-04-10T16:55:55.046+0200 to 2016-04-10T16:56:55.045+0200 through ntp_ntp_local_dateTime
2016-04-10 16:56:55.049 [INFO ] [marthome.event.ItemStateChangedEvent] - ntp_ntp_local_dateTime changed from 2016-04-10T16:55:55.046+0200 to 2016-04-10T16:56:55.045+0200
2016-04-10 16:57:08.332 [INFO ] [marthome.event.ItemStateChangedEvent] - FirstFloorHallMotionSensor changed from ON to OFF
2016-04-10 16:57:08.333 [INFO ] [marthome.event.ItemStateChangedEvent] - rfxcom_lighting2_A1WJD2HB_15669958_10_command changed from ON to OFF
2016-04-10 16:57:08.334 [INFO ] [marthome.event.ItemStateChangedEvent] - rfxcom_lighting2_A1WJD2HB_15669958_10_dimmingLevel changed from 100 to 0
2016-04-10 16:57:08.334 [INFO ] [marthome.event.ItemStateChangedEvent] - rfxcom_lighting2_A1WJD2HB_15669958_10_contact changed from OPEN to CLOSED
2016-04-10 16:57:13.444 [INFO ] [marthome.event.ItemStateChangedEvent] - MainHallMotionSensor changed from OFF to ON
2016-04-10 16:57:13.445 [INFO ] [marthome.event.ItemStateChangedEvent] - rfxcom_lighting2_A1WJD2HB_15663466_10_command changed from OFF to ON
2016-04-10 16:57:13.450 [INFO ] [marthome.event.ItemStateChangedEvent] - rfxcom_lighting2_A1WJD2HB_15663466_10_dimmingLevel changed from 0 to 100
2016-04-10 16:57:13.451 [INFO ] [marthome.event.ItemStateChangedEvent] - rfxcom_lighting2_A1WJD2HB_15663466_10_contact changed from CLOSED to OPEN
2016-04-10 16:57:23.053 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 10;1;1;0;0;6.3
2016-04-10 16:57:24.511 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 3;1;1;0;17;9223
2016-04-10 16:57:24.513 [INFO ] [marthome.event.ItemStateChangedEvent] - CurrentTotalPower changed from 6559 to 9223
2016-04-10 16:57:24.519 [INFO ] [marthome.event.ItemStateChangedEvent] - AverageTotalPower changed from 6559 to 9223
2016-04-10 16:57:24.798 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 3;1;1;0;17;9223
2016-04-10 16:57:25.616 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 3;1;1;0;24;4597
2016-04-10 16:57:27.075 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 3;1;1;0;24;4597
2016-04-10 16:57:29.766 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 3;1;1;0;24;4597
2016-04-10 16:57:31.128 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 3;1;1;0;18;4.6050

[TimO]

@kolaf : I'm glad the bindings are now working together.

The delay in the transmission is a bit strange. I've no idea where that could come from.
I've ported my production environment to OH2 and this didn't occure to me yet. I've upgraded a lot of my sensors to 2.0-beta and therefore took a closer look at the debug output of the OH2 binding to check if the devices present themself correctly and send the messages. I'll will keep an eye on it!

Currently I'm running OH2 with:

• Astro1
• Weather1
• MySensors2
• MySQL Persistence
• Sonos2

In the MySensors network I have a couple of Sensebender Micros, a shutter control with 12 SSR and two nodes to control LED lights plus selfmade DHT22 nodes connected to two gateways (one serial, one ethernet (iboard)).

I'm glad it runs stable for days now, although it is obvious in some places that this is a beta release of OH2. There are icons missing and there are bugs in the basicui and the documentation could be much better.

[Francois]

@TimO I try openHab 2.0 binding today and I am getting this where the serial changes from Initializing to Offline. Even if I reboot I get the same error. Why is this happing?

12:49:05.469 [DEBUG] [nsors.handler.MySensorsBridgeHandler] - Initialization of the MySensors Bridge
12:49:05.543 [DEBUG] [col.serial.MySensorsSerialConnection] - Connecting to /dev/ttyUSB0 [baudRate:115200]
12:49:06.140 [INFO ] [smarthome.event.ItemAddedEvent      ] - Item 'mysensors_bridge_ser_bb7302f6' has been added.
12:49:06.390 [DEBUG] [col.serial.MySensorsSerialConnection] - Successfully connected to serial port.
12:49:06.446 [INFO ] [rthome.event.ItemThingLinkAddedEvent] - Link 'mysensors_bridge_ser_bb7302f6-mysensors:bridge-ser:bb7302f6' has been added.
12:49:09.409 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 0;255;3;0;9;Starting gateway (RRNGA-, 2.0.0-beta)
12:49:09.426 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 0;255;3;0;9;Radio init successful.
12:49:09.434 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 0;255;3;0;14;Gateway startup complete.
12:49:09.441 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 0;255;3;0;9;Init complete, id=0, parent=0, distance=0
12:49:09.506 [DEBUG] [g.mysensors.protocol.MySensorsWriter] - Sending to MySensors: 0;0;3;0;2;
12:49:10.488 [WARN ] [ome.core.thing.internal.ThingManager] - Initializing handler for thing 'mysensors:bridge-ser:bb7302f6' takes more than 5000ms.
12:49:10.763 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 0;255;3;0;9;read: 40-40-0 s=1,c=1,t=16,pt=0,l=1,sg=0:1
12:49:10.767 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 40;1;1;0;16;1
12:49:11.676 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 0;255;3;0;9;read: 40-40-0 s=1,c=1,t=16,pt=0,l=1,sg=0:1
12:49:11.680 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 40;1;1;0;16;1
12:49:11.778 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 0;255;3;0;9;read: 40-40-0 s=0,c=1,t=23,pt=2,l=2,sg=0:72
12:49:11.783 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 40;0;1;0;23;72
12:49:11.792 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 0;255;3;0;9;read: 40-40-0 s=5,c=1,t=38,pt=7,l=5,sg=0:3.07
12:49:11.796 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 40;5;1;0;38;3.07
12:49:11.838 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 0;255;3;0;9;read: 40-40-0 s=5,c=1,t=38,pt=7,l=5,sg=0:3.07
12:49:11.843 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 40;5;1;0;38;3.07
12:49:11.861 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 0;255;3;0;9;read: 40-40-0 s=255,c=3,t=0,pt=1,l=1,sg=0:100
12:49:11.866 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 40;255;3;0;0;100
12:49:12.079 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 0;255;3;0;9;read: 66-66-0 s=1,c=1,t=24,pt=5,l=4,sg=0:3579898
12:49:12.083 [DEBUG] [g.mysensors.protocol.MySensorsReader] - 66;1;1;0;24;3579898
12:49:14.409 [ERROR] [s.internal.MySensorsBridgeConnection] - Cannot start reading/writing thread, probably sync message (I_VERSION) not received
12:49:14.410 [DEBUG] [col.serial.MySensorsSerialConnection] - Shutting down serial connection!
12:49:14.412 [DEBUG] [g.mysensors.protocol.MySensorsWriter] - Stopping Writer thread
12:49:14.418 [WARN ] [g.mysensors.protocol.MySensorsWriter] - Writer thread interrupted
12:49:14.428 [DEBUG] [g.mysensors.protocol.MySensorsReader] - Stopping Reader thread
12:49:14.528 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'mysensors:bridge-ser:bb7302f6' changed from INITIALIZING to OFFLINE
Insert Code Here

[andreacioni]

Hi @Francois ,

thanks for report. Seems that the you are using 2.0 version of MS Gateway. If you do not need it for particular task, try install the 1.5 version. I'll try to fix your problem as soon as possible!

[Francois]

@andreacioni Thanks for this all my sensor are running on version 2 so I don't know it my nodes will run on an 1.5 serial GW

[TimO]

I have a serial and ethernet gateway with version 2.0 running without any problems.
In your case there are a lot messages arriving within a short time, maybe that is the reason the gateway won't react on the I_VERSION message from the binding.

Please disable debugging in the gateway and try again. The reliability of my gateway improved a lot after disabling debugging.

[Francois]

@TimO I still get the same error after I disable debugging in the gateway

[andreacioni]

@Francois could you please send manually the I_VERSION command to the gateway? By no this is done by binding to check if the startup of the gateway was completed without errors. In your case that check fail. The I_VERSION message is this: 0;0;3;0;2;, you could try also 0;255;3;0;2; and see if gateway answer. Let we know what you see!

[Francois]

@andreacioni sorry how do I do this I_VERSION command to the gateway?

[andreacioni]

@Francois is a simple serial text message, just open the serial monitor of Arduino IDE and send it from there.

[Francois]

@andreacioni Here is is the info:

0;255;3;0;9;Starting gateway (RRNGA-, 2.0.0-beta)
0;255;3;0;9;Radio init successful.
0;255;3;0;14;Gateway startup complete.
0;255;3;0;9;Init complete, id=0, parent=0, distance=0
0;255;3;0;9;read: 40-40-0 s=1,c=1,t=16,pt=0,l=1,sg=0:1
40;1;1;0;16;1
0;255;3;0;9;read: 40-40-0 s=255,c=3,t=0,pt=1,l=1,sg=0:100
40;255;3;0;0;100
0;255;3;0;9;read: 40-40-0 s=1,c=1,t=16,pt=0,l=1,sg=0:1
40;1;1;0;16;1
0;255;3;0;9;read: 2-2-0 s=0,c=1,t=1,pt=7,l=5,sg=0:34.0
2;0;1;0;1;34.0
0;255;3;0;9;read: 40-40-0 s=1,c=1,t=16,pt=0,l=1,sg=0:0
40;1;1;0;16;0
0;255;3;0;9;read: 40-40-0 s=0,c=1,t=23,pt=2,l=2,sg=0:80
40;0;1;0;23;80
0;255;3;0;9;read: 40-40-0 s=255,c=3,t=0,pt=1,l=1,sg=0:100
40;255;3;0;0;100
0;255;3;0;9;read: 40-40-0 s=1,c=1,t=16,pt=0,l=1,sg=0:1
40;1;1;0;16;1
0;255;3;0;9;read: 101-101-0 s=255,c=3,t=15,pt=0,l=2,sg=0:

0;255;3;0;9;send: 0-0-101-101 s=255,c=3,t=15,pt=0,l=2,sg=0,st=fail:

0;255;3;0;9;read: 101-101-0 s=255,c=3,t=6,pt=1,l=1,sg=0:0
101;255;3;0;6;0
0;255;3;0;9;read: 101-101-0 s=255,c=3,t=6,pt=1,l=1,sg=0:0
101;255;3;0;6;0
0;255;3;0;9;read: 101-101-0 s=255,c=3,t=12,pt=0,l=3,sg=0:2.0
101;255;3;0;12;2.0

[andreacioni]

@Francois ok, this is the normal output. What happens if you send the I_VERSION message (just copy, paste and send one of them: 0;0;3;0;2; or 0;255;3;0;2; )?

UPDATE: Issue posted on tracker here