openhab / openhab1-addons

Add-ons for openHAB 1.x
Eclipse Public License 2.0
3.43k stars 1.7k forks source link

Modbus Binding stops updating Switches (openhab 2) #4870

Open mbs38 opened 7 years ago

mbs38 commented 7 years ago

Current Behavior

After a day or so of runtime the modbus binding stops updating (some) switches from OFF to ON.

The openhab command line report the state of the Switch item as OFF: status IRvorneEventRisingEdge OFF

I've sniffed the traffic on the bus and it clearly shows that the device reports the coil 25 to be ON: Request by openhab in hexadecimal: 05 01 00 00 00 28 3D 90 Response from the device: 05 01 05 00 1F 1F 1A 1B ED D8 Coil 25 is located in the seventh byte (value 1A) in which the corresponding bit is set.

The state of the Switch in openhab is therefore out of sync with the actual value on the serial bus.

Steps to Reproduce (for bugs)

modbus.cfg (excerpt): modbus:serial.agsBus5coils.connection=/dev/ttyS0:38400:8:none:1:rtu:3 modbus:serial.agsBus5coils.id=5 modbus:serial.agsBus5coils.start=0 modbus:serial.agsBus5coils.length=40 modbus:serial.agsBus5coils.type=coil

.items-File (excerpt): Switch IRvorneEventRisingEdge { modbus="agsBus5coils:25" }

rules affecting the item: when Item IRvorneEventRisingEdge changed from OFF to ON then logInfo("agsRules","Bewegungsmelder vorne ausgelöst.") if(IRvorneAusgeschaltet.state == OFF && Holztuer.state == CLOSED) { sendCommand(agsBusMasterSoundToIntercomRelay, ON) sendCommand(agsGongen, ON) Thread::sleep(9999) sendCommand(IRvorneEventRisingEdge, OFF) } else { sendCommand(IRvorneEventRisingEdge, OFF) } end

Context

An infrared sensor is connected to an input of a Modbus device. The Modbus device sets a coil to ON when it detects a rising edge on the corresponding input. In order to detect another rising edge, the coil has to be set back to OFF manually by the busmaster. This is accomplishd by the rule

Your Environment

ARCH Linux (4.8.2-1-ARCH)

java -version openjdk version "1.8.0_102" OpenJDK Runtime Environment (build 1.8.0_102-b14) OpenJDK 64-Bit Server VM (build 25.102-b14, mixed mode)

Current openhab 2.0 snapshot.

ssalonen commented 7 years ago

Thanks for reporting this.

I believe you are using 1.9.0? If not, please update to latest 1.9.0 snapshot.

Do you get any errors in the logs?

Would you still get the wrong behavior id updateunchangeditems is set to true?

Best Sami

mbs38 commented 7 years ago

Hi Sami, thanks for the quick response. Unfortunately there are no errors in the logs.

I'll try the updateunchangeditems options, although I would prefer not to activate it in the long haul since it causes enormous CPU load. I've added: modbus:serial.agsBus5coils.updateunchangeditems=true

Could you point me to the location of the newest version of the binding?

Best regards, Max

ssalonen commented 7 years ago

Hi

Here's the link https://openhab.ci.cloudbees.com/job/openHAB1-Addons/lastSuccessfulBuild/artifact/bundles/binding/org.openhab.binding.modbus/target/org.openhab.binding.modbus-1.9.0-SNAPSHOT.jar

Yeah was proposing the setting to rule that one out..

Best Sami

mbs38 commented 7 years ago

Hi I'm currently running my system with the latest snapshot and without the updateunchangeditems option. I'll report back if the problem appears again.

Best Max

mbs38 commented 7 years ago

For the sake of completeness: the issue hasn't occured again. Sry for not reporting back sooner.

ssalonen commented 7 years ago

@mbs38 but it did occur consistently with updateunchangeditems=false?

mbs38 commented 7 years ago

For the last 4 weeks it has worked perfectly well without updateunchangeditems=true.

ssalonen commented 7 years ago

So that means it works with updateunchangeditems=false even though nothing has changed in the binding...

Perhaps fixed by nrjavaserial update recently?

Anyway, please report back if it happens again!

mbs38 commented 7 years ago

Hello, the problem has appeared again. I was again able to confirm that the data one the serial bus is out of sync with the item state in openhab. -.-

ssalonen commented 7 years ago

Hi!

Some basic easy questions to rule out easy cases.

Are you updating the state of the items in openhab, e.g using rules?

Could you please try to reproduce the issue with updateunchangeditems as true?

Can you reproduce the issue easily or does it take a long time? It would help the debugging if you can make the bug appear with a test tcp server (eg diagslave).

Best Sami

mbs38 commented 7 years ago

Hi Sami, I'm using rules to send commands to the items, sth. like:

rule "someRule" when Item itemOfCoil0 changed from OFF to ON then logInfo("myRuleLog", "item0Coil0 blah...") sendCommand(itemOfCoil0, OFF) end

Background: There is a Modbus device that detect events (rising edges at its inputs). The device sets a coil to ON when a rising edge has been detected. In order to be able to detect another rising edge the coil has to be set to OFF again by openhab.

It takes weeks for the issue to appear in my setup. I'll try updateunchangeditems=true in my productive setup in the hope that it solves the issue for that setup.

I'll also try to come up with a test setup that makes it more likely that the problem appears.

Max

ssalonen commented 7 years ago

Thanks for the information.

I guess that rule should not put it out of sync since it just an command, the actual item state is updated on next poll. I might be missing something also.

I wonder if can reproduce the issue using a test server, and a separate (python?) script that "toggles" the server coil bits?

Anyways, I think this issue should be re-opened?

ssalonen commented 7 years ago

I think I can reproduce the issue:

Steps to reproduce

  1. start server ./diagslave -p 55502
  2. Poll current value ./modpoll 127.0.0.1 -t 0 -p 55502 -l 1500 (have this in separate terminal)
  3. start openhab (see config below)
  4. Set coil on with a fast pace ./modpoll 127.0.0.1 -t 0 -p 55502 1

Configuration

items:

Contact ModbusItem "Dimmer1 [%d]" (ALL) {modbus="slave1:0"}

Rules:

rule "someRule"
when
    Item ModbusItem changed from CLOSED to OPEN
then
    logInfo("myRuleLog", "item0Coil0 blah...")
    sendCommand(ModbusItem, CLOSED)
end

openhab.cfg:

modbus:poll=500
modbus:tcp.slave1.connection=127.0.0.1:55502:0:0:0:1
modbus:tcp.slave1.type=coil
modbus:tcp.slave1.length=20
modbus:tcp.slave1.updateunchangeditems=false
modbus:tcp.slave1.postundefinedonreaderror=true

Expected result

Actual result

other info

I cannot reproduce the issue with updateunchangeditems=true.

Proposed solution

I'm guessing this can be a race condition when reading the data, will report back if this hypothesis turns out to be correct...

ssalonen commented 7 years ago

When investigating further my example seems to be a possible race condition with the rule setup:

Good case:

  1. polling value 0 -> state updated
  2. polling value 1 -> state updated
  3. rule triggered, command=0 sent
  4. polling value 0 -> state updated

Bad case:

  1. polling value 0 -> state updated
  2. polling value 1 -> state updated
  3. rule triggered, command=0 sent (coil updated to 1)
  4. polling value 1 -> not updating state since polled value has not changed between polls. However, openhab item state has been changed to zero due to event bus command in step 3
  5. Result is that openhab item state is zero, but true coil value is 1

I had the impression initially that the command do not change the item state but seeing the results I might have been wrong. Do you know better? Could you try to verify this procedure as well (I think it might be easier with long poll period)?

Best, Sami

9037568 commented 7 years ago

Reopened, per request.

Rossko57 commented 7 years ago

Comment - would autoupdate="false" applied to the Item be a fix?

mbs38 commented 7 years ago

Hey Sami, I'm sorry for not having replied to this sooner but I had completely forgotten about it because updateunchangeditems=true seems to have fixed it.

Max

Rossko57 commented 7 years ago

I still believe autoupdate="false" is required here, as a good practice. By default, when you send a command to an Item "the system" will update its .state, at some time, independently of the binding. Maybe before, maybe after the binding does its thing (i.e. writes over modbus) So item.state may or may not reflect reality until the next read poll. This is Sami's Bad Case point {4).

There are apparently ways for the binding to inhibit autoupdate, but as it is not generally required I think it can be left to the user to apply autoupdate="false" only where needed.

useful explanation