search

Teekanne / openhab

Automatically exported from code.google.com/p/openhab
0 stars 0 forks source link

modbus serial binding doesn't work in 1.3.0 #426

Closed GoogleCodeExporter closed 9 years ago

GoogleCodeExporter commented 9 years ago 
I'm using openhab modbus binding together with Arduino. Modbus works properly 
in openhab 1.2.0 but it doesn't work in openhab 1.3.0 SNAPSHOT.

What steps will reproduce the problem?
1. Download distribution-1.3.0-SNAPSHOT-runtime.zip, 
distribution-1.3.0-SNAPSHOT-addons.zip and distribution-1.3.0-SNAPSHOT-demo.zip

2. Install openhab 1.3.0-SNAPSHOT as described  here 
https://code.google.com/p/openhab/wiki/Setup

3. Copy modbus binding from distribution-1.3.0-SNAPSHOT-addons.zip into 
installed openhab addons directory

4. Configure modbus:
modbus:poll=200
modbus:serial.slave1.connection=/dev/ttyUSB0:115200
modbus:serial.slave1.id=1
modbus:serial.slave1.start=0
modbus:serial.slave1.length=9
modbus:serial.slave1.type=holding

5. Add binding to some item. For example:
Switch Audio_Edifier_Power  "Power" (G_Edifier) {modbus="slave1:<0:>0"}

6. Start openhab:
sudo ./start_debug.sh

What is the expected output? What do you see instead?
Steps above work good in stable openhab 1.2.0 - openhab reads/writes modbus 
registers. I'm using modbus master with led indications for Tx/Rx operations. I 
see that these Tx/Rx leds begin flashing when openhab is running. And of course 
I see that it works on my device.

The same steps don't work in latest openhab 1.3.0 SNAPSHOT - openhab doesn't 
read/write modbus registers. There are no errors in openhab output:

$ sudo ./start_debug.sh | grep -i 'modbus'
22:43:30.742 DEBUG o.o.b.m.i.ModbusActivator[:50] - Modbus binding has been 
started.
22:43:30.748 DEBUG o.o.m.i.i.GenericItemProvider[:312] - Start processing 
binding configuration of Item 'Audio_Edifier_Power (Type=SwitchItem, 
State=Uninitialized)' with 'ModbusGenericBindingProvider' reader.
22:43:30.754 DEBUG o.o.m.i.i.GenericItemProvider[:312] - Start processing 
binding configuration of Item 'Audio_Edifier_VolumeMute (Type=SwitchItem, 
State=Uninitialized)' with 'ModbusGenericBindingProvider' reader.
22:43:30.758 DEBUG o.o.m.i.i.GenericItemProvider[:312] - Start processing 
binding configuration of Item 'Audio_Edifier_VolumeInc (Type=SwitchItem, 
State=Uninitialized)' with 'ModbusGenericBindingProvider' reader.
22:43:30.769 DEBUG o.o.m.i.i.GenericItemProvider[:312] - Start processing 
binding configuration of Item 'Audio_Edifier_VolumeDec (Type=SwitchItem, 
State=Uninitialized)' with 'ModbusGenericBindingProvider' reader.
22:43:30.770 DEBUG o.o.m.i.i.GenericItemProvider[:312] - Start processing 
binding configuration of Item 'Audio_Edifier_InputFM (Type=SwitchItem, 
State=Uninitialized)' with 'ModbusGenericBindingProvider' reader.
22:43:30.770 DEBUG o.o.m.i.i.GenericItemProvider[:312] - Start processing 
binding configuration of Item 'Audio_Edifier_InputPC (Type=SwitchItem, 
State=Uninitialized)' with 'ModbusGenericBindingProvider' reader.
22:43:30.771 DEBUG o.o.m.i.i.GenericItemProvider[:312] - Start processing 
binding configuration of Item 'Audio_Edifier_Station1 (Type=SwitchItem, 
State=Uninitialized)' with 'ModbusGenericBindingProvider' reader.
22:43:30.772 DEBUG o.o.m.i.i.GenericItemProvider[:312] - Start processing 
binding configuration of Item 'Audio_Edifier_Station2 (Type=SwitchItem, 
State=Uninitialized)' with 'ModbusGenericBindingProvider' reader.
RXTX Warning:  Removing stale lock file. /var/lock/LCK..ttyUSB0

What version of the product are you using? On what operating system?
Ubuntu 13.04
openhab 1.2.0 - works fine
openhab 1.3.0 SNAPSHOT - doesn't work

Please provide any additional information below.
WiKi page https://code.google.com/p/openhab/wiki/ModbusTcpBinding is out of 
date and doesn't containe information about how to configure modbus serial. I 
was able to configure it and get it running after source code investigation

Original issue reported on code.google.com by igor.zel...@gmail.com on 27 Aug 2013 at 8:29

GoogleCodeExporter commented 9 years ago 
One more important note. Openhab 1.2.0 starts polling modbus slaves after this 
line in output:
23:47:26.721 DEBUG o.o.c.s.AbstractActiveService[:164] - Modbus Polling Service 
has been started

This line doesn't appear in output of openhab 1.3.0 SNAPSHOT. So looks like 
problem is this Modbus Polling Service. It starts in 1.2.0 and doesn't start in 
1.3.0 SNAPSHOT.

Original comment by igor.zel...@gmail.com on 27 Aug 2013 at 8:52

GoogleCodeExporter commented 9 years ago 
which build version is your snapshot?

Original comment by teichsta on 27 Aug 2013 at 9:33

GoogleCodeExporter commented 9 years ago 
Where can I found build version?

I downloaded it 26/08/2013 from here: 
https://openhab.ci.cloudbees.com/job/openHAB/. So I guess build version is 466.

Original comment by igor.zel...@gmail.com on 27 Aug 2013 at 10:33

GoogleCodeExporter commented 9 years ago 
I was not able to reproduce this issue under debugger with a latest code and 
with the same configuration files.

Under debugger openhap is polling modbus slave.

Original comment by igor.zel...@gmail.com on 29 Aug 2013 at 10:43

GoogleCodeExporter commented 9 years ago 
Hi,

I was managed to understand why it doesn't work.

I started openhab with start_debug.sh and then connected to it with remote 
dubugging session.

So modbus binding at 1.3.0 SNAPSHOT doesn't work because openhab calls this 
code:

    public void setModbusBinding(ModbusBinding binding) {
        this.binding = binding;
        setProperlyConfigured(!ModbusConfiguration.getAllSlaves().isEmpty());
    }

before establishing connectios with modbuss slaves. So as result 
ModbusConfiguration.getAllSlaves().isEmpty() returns TRUE.

And if I'm running openhab from Eclipse (local debugging session) then openhab 
firstly establishes connections to slaves and only after that calls 
setModbusBinding method. So in this case 
ModbusConfiguration.getAllSlaves().isEmpty() returns FALSE.

So the reason is incorrect order of calling initialization code at startup.

I guess it is related to threading...

Can somebody take a look at it please?

Original comment by igor.zel...@gmail.com on 1 Sep 2013 at 8:52

GoogleCodeExporter commented 9 years ago 
Hi,

same in TCP Part of 1.3:

My Configuration:
modbus:poll=1000

modbus:tcp.slave11.connection=192.168.0.49:502
modbus:tcp.slave11.id=1
modbus:tcp.slave11.start=4143
modbus:tcp.slave11.length=1
modbus:tcp.slave11.type=holding

modbus:tcp.slave12.connection=192.168.0.49:502
modbus:tcp.slave12.id=1
modbus:tcp.slave12.start=4142
modbus:tcp.slave12.length=1
modbus:tcp.slave12.type=holding

Debug:
19:21:24.248 DEBUG o.o.b.m.i.ModbusActivator[:50] - Modbus binding has been 
started.
19:21:24.248 DEBUG o.o.m.i.i.GenericItemProvider[:312] - Start processing 
binding configuration of Item 'Watchdog_tout (Type=NumberItem, 
State=Uninitialized)' with 'ModbusGenericBindingProvider' reader.
19:21:24.248 DEBUG o.o.m.i.i.GenericItemProvider[:312] - Start processing 
binding configuration of Item 'Watchdog_value (Type=NumberItem, 
State=Uninitialized)' with 'ModbusGenericBindingProvider' reader.
...

No update, no polling

Original comment by Helmut.L...@gmail.com on 8 Sep 2013 at 5:28

GoogleCodeExporter commented 9 years ago 
Hi,

you wrote:
> same in TCP Part of 1.3:
> ...
> No update, no polling

does it work in openhab 1.2?

Original comment by igor.zel...@gmail.com on 8 Sep 2013 at 7:13

GoogleCodeExporter commented 9 years ago 
Hi,

the 1.2 Version works!

Original comment by Helmut.L...@gmail.com on 9 Sep 2013 at 6:56

GoogleCodeExporter commented 9 years ago 
Issue 435 has been merged into this issue.

Original comment by teichsta on 9 Sep 2013 at 6:58

GoogleCodeExporter commented 9 years ago

Original comment by teichsta on 9 Sep 2013 at 6:58

GoogleCodeExporter commented 9 years ago 
Hi,

starting OH 1.3 with start.bat:
   ID|State      |Level|Name
  224|Active     |    1|openHAB ModbusTCP Master Binding (1.3.0.201309081519)

starting OH 1.3 in Eclipse:
   ID|State      |Level|Name
  107|Active     |    4|openHAB ModbusTCP Master Binding (1.3.0.qualifier)

A workaround is, to restart Modbus Bundle:
1. Press <Enter> to get osgi console -> osgi>
2. osgi> stop 224 (use your ID from "osgi> lb" command)
3. osgi> start 224

Then Modbus Polling starts correctly.

Played around with -Dfelix.fileinstall.active.level and 
-Dfelix.fileinstall.start.level in start.bat, nothing changed.
(http://felix.apache.org/site/apache-felix-framework-configuration-properties.ht
ml)

The start behavior of osgi is something obscure for me, because it is a 
confusing summation of several dependencies.
Therefore I think dependencies have to be resolved in the Bundles itself?!

Original comment by Helmut.L...@gmail.com on 9 Sep 2013 at 1:34

GoogleCodeExporter commented 9 years ago

Original comment by teichsta on 12 Sep 2013 at 12:43

GoogleCodeExporter commented 9 years ago 
I can confirm that workaround with restarting Modbus Bundle works.
So it means that something goes wrong on startup...

Original comment by igor.zel...@gmail.com on 17 Sep 2013 at 7:46

GoogleCodeExporter commented 9 years ago 
fixed this issue with 
http://code.google.com/p/openhab/source/detail?r=100877514e0babd79095d062c13a51f
b0e370ad5&name=1.3.1.

I started the CI build recently. Since i have no Modbus Hardware in place can 
please anybody confirm that this fix is working?

Original comment by teichsta on 18 Sep 2013 at 2:20

GoogleCodeExporter commented 9 years ago 
Cool! thank you! I will check it in the couple of hours.

Original comment by igor.zel...@gmail.com on 18 Sep 2013 at 2:25

GoogleCodeExporter commented 9 years ago 
Thomas, it works fine. I tested it with Arduino. Thank you a lot!!!

Just one note. Now it prints (to log) item state for every polling update. So 
for example I have this configuration: modbus:poll=100

As result it prints item state every ~100 ms.

20:52:00.622 INFO  runtime.busevents[:46] - Light_GF_Corridor_Ceiling state 
updated to OFF
20:52:00.737 INFO  runtime.busevents[:46] - Light_GF_Corridor_Ceiling state 
updated to OFF
20:52:00.851 INFO  runtime.busevents[:46] - Light_GF_Corridor_Ceiling state 
updated to OFF
20:52:00.965 INFO  runtime.busevents[:46] - Light_GF_Corridor_Ceiling state 
updated to OFF
20:52:01.079 INFO  runtime.busevents[:46] - Light_GF_Corridor_Ceiling state 
updated to OFF
20:52:01.194 INFO  runtime.busevents[:46] - Light_GF_Corridor_Ceiling state 
updated to OFF
20:52:01.309 INFO  runtime.busevents[:46] - Light_GF_Corridor_Ceiling state 
updated to OFF
20:52:01.424 INFO  runtime.busevents[:46] - Light_GF_Corridor_Ceiling state 
updated to OFF
20:52:01.538 INFO  runtime.busevents[:46] - Light_GF_Corridor_Ceiling state 
updated to OFF
20:52:01.653 INFO  runtime.busevents[:46] - Light_GF_Corridor_Ceiling state 
updated to OFF
20:52:01.768 INFO  runtime.busevents[:46] - Light_GF_Corridor_Ceiling state 
updated to OFF
20:52:01.881 INFO  runtime.busevents[:46] - Light_GF_Corridor_Ceiling state 
updated to OFF
20:52:01.995 INFO  runtime.busevents[:46] - Light_GF_Corridor_Ceiling state 
updated to OFF
20:52:02.109 INFO  runtime.busevents[:46] - Light_GF_Corridor_Ceiling state 
updated to OFF
20:52:02.221 INFO  runtime.busevents[:46] - Light_GF_Corridor_Ceiling state 
updated to OFF
20:52:02.335 INFO  runtime.busevents[:46] - Light_GF_Corridor_Ceiling state 
updated to OFF
20:52:02.449 INFO  runtime.busevents[:46] - Light_GF_Corridor_Ceiling state 
updated to OFF
20:52:02.562 INFO  runtime.busevents[:46] - Light_GF_Corridor_Ceiling state 
updated to OFF
20:52:02.676 INFO  runtime.busevents[:46] - Light_GF_Corridor_Ceiling state 
updated to OFF
20:52:02.790 INFO  runtime.busevents[:46] - Light_GF_Corridor_Ceiling state 
updated to OFF
20:52:02.904 INFO  runtime.busevents[:46] - Light_GF_Corridor_Ceiling state 
updated to OFF

So as result I have too many logs and it is hard to find something there. In 
1.2.0 it printed state only when it was changed.

But in general it works.

Original comment by igor.zel...@gmail.com on 18 Sep 2013 at 6:02

GoogleCodeExporter commented 9 years ago 

1)
Modbus Binding now starts and connects as expected at openHAB startup.

2)
And after a network interruption ...
17:33:22.266 DEBUG o.o.b.m.internal.ModbusSlave[:337] - ModbusSlave:Executing 
transaction failed (tried 3 times)
17:33:22.266 INFO  o.o.b.m.internal.ModbusSlave[:305] - ModbusSlave error 
getting responce from slave
java.net.SocketException: Connection reset
...
... it reconnects:
17:33:22.273 DEBUG o.o.b.m.internal.ModbusSlave[:337] - ModbusSlave:Executing 
transaction failed (tried 3 times)
17:33:22.273 INFO  o.o.b.m.internal.ModbusSlave[:305] - ModbusSlave error 
getting responce from slave
17:33:27.294 INFO  runtime.busevents[:46] - DI02_count_lo state updated to 51946
17:33:27.295 INFO  runtime.busevents[:46] - DI04_count_lo state updated to 20778

3)
Now, I only get update-Event-INFO.

It works perfect for me.

Thank You Thomas.

Original comment by Helmut.L...@gmail.com on 20 Sep 2013 at 3:43