OH2: onewire binding stops operation

Setup, Configuration and Use Beginners
1

Platform information:

  • Hardware: Raspi 3b+
  • OS: Linux openhab 4.14.79-v7+ #1159 SMP Sun Nov 4 17:50:20 GMT 2018 armv7l GNU/Linux
  • Java Runtime Environment: java-common 0.58

*Environment: openHAB 2.4.0.RC1 Milestone Build

*openHAB binding: onewire:digitalio2 by Jan N. Klug

*Oweserver: 3.1p5-1 (stretch standard apt installed)

*Situation:

One Onewire bus with multiple DS18B20 temp sensors, DS2438 humidity sensors, DS2413 gpio relais controller

The Onewire setup was working well unit I attached the DS2413 gpio relais controller.

DS2413 is correctly detected in the Paper UI Inbox.

The openHAB thing type is “digitalio2” and it has two channels. The channel are configured to OUTPUT channels, because I’d like to switch an attached relais card.

The problem starts when I use e.g. the Paper UI control dashboard to toggle that DS2413 channel status e.g. from OFF to ON I cause a reproducible “crash” the the whole onewire binding.

*Problem:

The effect is exactly the following:

  1. I set the onewire-binding log level to TRACE

  2. I see a lot of sensor communication logging flying though the log tail.

  3. I watch the log tail while toggling the DS2413 channel status

  4. The DS2413 toggle is seen in the log but not executed

  5. the logging is completely stopped and the whole onewire communication is halted

INFO_A: for information, at the same time I verify the correct working of the owserver by sending a

“owwrite 3A.812B00000000/PIO.A 1”

That is still working fine and the relais-A is activated.

INFO_B: tested with two DS2413 boards. Both show the same crashing behavior.

INFO_C: the “crash” situation is recovering by restarting the openhab2 service.

Is anybody successfully using this Dallas Onewire chip with openHAB? Any hint is very much welcome.

2

The paperUI is not for controlling things and channels, you should use an item and sitemap and/or the REST API.
Try that way and see if the error still occurs.

3

Created a switch item and added it to my default .sitemap. When switch the state, the same problem occurs like describerd above.
There is no difference between switching the item in the PaperUI contral dashboard or switching the item in a .sitemap.The onewire-binding TRACE log also stops logging after addressing the DS2413 digitalio2 channel.

4

It may be worth filing a bug report in gitHub

5

This is an extract of the owser log output
first the normal background operation when no comand is send to the onewire device

Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: handler.c:(153) START handler /3A.304455000000/PIO.BYTE

Dec 1 17:52:18 openHAB OWFS[10364]: CALL: data.c:(103) DataHandler: parse path=/3A.304455000000/PIO.BYTE
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_parseobject.c:(163) /3A.304455000000/PIO.BYTE
Dec 1 17:52:18 openHAB OWFS[10364]: CALL: ow_parsename.c:(104) path=[/3A.304455000000/PIO.BYTE]
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_regex.c:(154) Not found
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_regex.c:(201) 0: 0->15 found <><3A.304455000000><>
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_regex.c:(201) 1: 0->2 found <><3A><.304455000000>
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_regex.c:(201) 2: 3->15 found <3A.><304455000000><>
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_cache.c:(912) Looking for device 3A 30 24 46 00 00 00 7C
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_cache.c:(1070) Search in cache sn 3A 30 24 46 00 00 00 7C pointer=0x76f058e0 index=0 size=4
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_cache.c:(1086) Value found in cache. Remaining life: 120 seconds.
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_presence.c:(75) Found device on bus 0
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_regex.c:(201) 0: 3->4 found <.>
Dec 1 17:52:18 openHAB OWFS[10364]: CALL: data.c:(144) Read message
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: read.c:(55) ReadHandler start
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: read.c:(61) ReadHandler: From Client sm->payload=26 sm->size=4096 sm->offset=0
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: read.c:(79) ReadHandler: call FS_read_postparse on /3A.304455000000/PIO.BYTE
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_read.c:(72) /3A.304455000000/PIO.BYTE
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_read.c:(204) /3A.304455000000/PIO.BYTE
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_read.c:(238) About to read </3A.304455000000/PIO.BYTE> extension=-2 size=12 offset=0
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_read.c:(333) file_length=12 offset=0 size=12
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_read.c:(401) Read an aggregate .BYTE /3A.304455000000/PIO.BYTE
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_parseobject.c:(74) Path /3A.304455000000/PIO.BYTE is an agggregate
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_parseobject.c:(94) Create sibling piostate from /3A.304455000000/PIO.BYTE as /3A.304455000000/piostate
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_parseobject.c:(29) /3A.304455000000/piostate
Dec 1 17:52:18 openHAB OWFS[10364]: CALL: ow_parsename.c:(104) path=[/3A.304455000000/piostate]
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_regex.c:(154) Not found
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_regex.c:(201) 0: 0->15 found <><3A.304455000000><>
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_regex.c:(201) 1: 0->2 found <><3A><.304455000000>
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_regex.c:(201) 2: 3->15 found <3A.><304455000000><>
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_cache.c:(912) Looking for device 3A 30 24 46 00 00 00 7C
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_cache.c:(1070) Search in cache sn 3A 30 24 46 00 00 00 7C pointer=0x76f058e0 index=0 size=4
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_cache.c:(1086) Value found in cache. Remaining life: 120 seconds.
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_presence.c:(75) Found device on bus 0
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_regex.c:(154) Not found
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_read.c:(333) file_length=12 offset=0 size=1
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_cache.c:(835) 3A 30 44 55 00 00 00 7C size=8 IsUncachedDir=0
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_cache.c:(1070) Search in cache sn 3A 30 24 46 00 00 00 7C pointer=0x76ef06b8 index=0 size=8
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_cache.c:(1086) Value found in cache. Remaining life: 15 seconds.
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_read.c:(626) Data obtained from cache
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_parsename.c:(63) /3A.304455000000/piostate
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_read.c:(620) Read /3A.304455000000/PIO.BYTE Extension -2 Gives result 0
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_read.c:(253) return=0
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_read.c:(263) After read is performed (bytes or error 12)
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_read.c:(226) /3A.304455000000/PIO.BYTE returns 12
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_read.c:(103) /3A.304455000000/PIO.BYTE return 12
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: read.c:(81) ReadHandler: FS_read_postparse read on /3A.304455000000/PIO.BYTE return = 12
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: read.c:(89) ReadHandler: FS_read_postparse ok size=12
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: read.c:(100) ReadHandler: To Client cm->payload=12 cm->size=12 cm->offset=0
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: data.c:(146) Read message done value=0x71f14998
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_parsename.c:(63) /3A.304455000000/PIO.BYTE
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: data.c:(193) DataHandler: FS_ParsedName_destroy done
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: data.c:(207) DataHandler: cm.ret=12
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: to_client.c:(76) payload=12 size=12, ret=12, sg=0x104 offset=0
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: data.c:(226) Finished with client request
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: handler.c:(132) OWSERVER tcp connection persistence – reusing connection now.
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_tcp_read.c:(63) attempt 24 bytes Time: 10.000000 seconds
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_tcp_read.c:(113) read: 24 - 0 = 24
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: from_client.c:(66) FromClient payload=16 size=4096 type=6 sg=0x124 offset=0
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: from_client.c:(74) FromClient (no servermessage) payload=16 size=4096 type=6 controlflags=0x124 offset=0
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_tcp_read.c:(63) attempt 16 bytes Time: 10.000000 seconds
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: ow_tcp_read.c:(113) read: 16 - 0 = 16
Dec 1 17:52:18 openHAB OWFS[10364]: DEBUG: handler.c:(73) Persistence requested

This is what is show in the log after toggeling the edvice ON or OFF.

Dec 1 17:55:14 openHAB OWFS[10364]: DEBUG: handler.c:(132) OWSERVER tcp connection persistence – reusing connection now.
Dec 1 17:55:14 openHAB OWFS[10364]: DEBUG: ow_tcp_read.c:(63) attempt 24 bytes Time: 10.000000 seconds
Dec 1 17:55:14 openHAB OWFS[10364]: DEBUG: ow_tcp_read.c:(113) read: 24 - 24 = 0
Dec 1 17:55:14 openHAB OWFS[10364]: DEBUG: handler.c:(135) OWSERVER handler done
Dec 1 17:55:14 openHAB OWFS[10364]: DEBUG: ow_net_server.c:(259) Normal completion.
Dec 1 17:55:14 openHAB OWFS[10364]: DEBUG: ow_tcp_read.c:(63) attempt 24 bytes Time: 10.000000 seconds
Dec 1 17:55:14 openHAB OWFS[10364]: DEBUG: ow_tcp_read.c:(113) read: 24 - 0 = 24
Dec 1 17:55:14 openHAB OWFS[10364]: DEBUG: from_client.c:(66) FromClient payload=2 size=4096 type=3 sg=0x104 offset=0
Dec 1 17:55:14 openHAB OWFS[10364]: DEBUG: from_client.c:(74) FromClient (no servermessage) payload=2 size=4096 type=3 controlflags=0x104 offset=0
Dec 1 17:55:14 openHAB OWFS[10364]: DEBUG: ow_tcp_read.c:(63) attempt 2 bytes Time: 10.000000 seconds
Dec 1 17:55:14 openHAB OWFS[10364]: DEBUG: ow_tcp_read.c:(113) read: 2 - 0 = 2
Dec 1 17:55:14 openHAB OWFS[10364]: DEBUG: from_client.c:(109) Data size mismatch
Dec 1 17:55:14 openHAB OWFS[10364]: DEBUG: handler.c:(135) OWSERVER handler done
Dec 1 17:55:14 openHAB OWFS[10364]: DEBUG: ow_net_server.c:(259) Normal completion.

After the last line there is no onewire activity going on any more.

6

I‘ll check that. Probably something is wrong with the way the binding writes to the owserver.

7

Silly mistake. Please try this. It already includes the initialization fix.

1 Like
8

Hello Jan,

thanks for the fast reaction!

I have put the binding .jar file to the “/usr/share/openhab2/addons” directory

openhab> list | grep Wire
196 x Active x 80 x 0.10.0.oh240 x Eclipse SmartHome OneWire Binding
211 x Installed x 80 x 0.10.0.201812230956 x Eclipse SmartHome OneWire Binding

I have removed the original oh240 binding and activated your binding

openhab> bundle:list | grep Wire
211 x Active x 80 x 0.10.0.201812230956 x Eclipse SmartHome OneWire Binding

I restarted oh2, but unfortunately I still experience the bug.

When activating the relais via the 29.xxxxxxxxx in the basicUI, the binding stops its operation immediately, while I still can control the relais via owwrite.

Dec 23 23:55:07 openhab OWFS[2648]: DEBUG: ow_tcp_read.c:(63) attempt 24 bytes Time: 10.000000 seconds
Dec 23 23:55:07 openhab OWFS[2648]: DEBUG: ow_tcp_read.c:(113) read: 24 - 0 = 24
Dec 23 23:55:07 openhab OWFS[2648]: DEBUG: from_client.c:(66) FromClient payload=25 size=4096 type=3 sg=0x104 offset=0
Dec 23 23:55:07 openhab OWFS[2648]: DEBUG: from_client.c:(74) FromClient (no servermessage) payload=25 size=4096 type=3 controlflags=0x104 offset=0
Dec 23 23:55:07 openhab OWFS[2648]: DEBUG: ow_tcp_read.c:(63) attempt 25 bytes Time: 10.000000 seconds
Dec 23 23:55:07 openhab OWFS[2648]: DEBUG: ow_tcp_read.c:(113) read: 25 - 0 = 25
Dec 23 23:55:07 openhab OWFS[2648]: DEBUG: from_client.c:(109) Data size mismatch
Dec 23 23:55:07 openhab OWFS[2648]: DEBUG: handler.c:(135) OWSERVER handler done
Dec 23 23:55:07 openhab OWFS[2648]: DEBUG: ow_net_server.c:(259) Normal completion.

best regards,
Martin

9

That‘s strange. I‘ll check again, probably on Tuesday. I thought my packet looked the same as the one from owwrite. Thanks.

10

There was a small, but significant difference. I’ve updated the JAR above and at least for me it works. Please check.

11

Hello Jan,

you are super fast.

What a Christmas present.

I just tested the new snapshot and my OneWire Octal Relais Boards started switching like a charm.

Thanks a lot for the fix and Merry Christmas!

Martin

12

just checked the logs again and one tiny issue remains.
Seems to be more on the cosmetic side because the switch action as well as the switch status display work fine.
But I think it might be still worth to mention here.

2018-12-25 00:54:49.123 [ome.event.ItemCommandEvent] - Item ‘OctalDigitalIO29FE3F34000000_DigitalIO0’ received command OFF

2018-12-25 00:54:49.144 [nt.ItemStatePredictedEvent] - OctalDigitalIO29FE3F34000000_DigitalIO0 predicted to become OFF

2018-12-25 00:54:49.155 [vent.ItemStateChangedEvent] - OctalDigitalIO29FE3F34000000_DigitalIO0 changed from ON to OFF

==> /var/log/openhab2/openhab.log <==

2018-12-25 00:54:54.343 [INFO ] [ernal.device.AbstractDigitalOwDevice] - could not write OFF to 0: I/O error: exception while reading packet - Read timed out

13

Fixed. Just a wrong error message. I created PR #6725.