Error with onewire owfs-number access: Read timed out although accessible via owhttp

Fuzzy · February 12, 2020, 10:36pm

Hi all,

… migrating my onewire sensors from an old wiregate installation to openhab. Trying to get a hold on things. So far so good, I was able to setup devices, discover sensors via Paper UI and access a specific element via owfs-number and a path.

Specifically these channel worked / are still working:

        Type owfs-number : OW_All_Errors_CRC8     "CRC8 Errors"             [ path="statistics/errors/CRC8_errors", refresh = 60 ]
        Type owfs-number : ow_test            "UG Schleuse Temp (via path)" [ path="28.3755CF040000/temperature12", refresh = 60 ]

Now, I’m trying to get a hold on the busmaster statistics. For this, I added several channels to the OW Bridge / Server (in the listing at the end):

Bridge onewire:owserver:sensix "Sensix 1Wire Bridge" @ "HWR" [ network-address="xxxx" ] {
      /*
        ****************** Bus 0 --> Busmaster 81.AFA135000000, Number 4
        ****************** Devices
      */
      Thing bms UG_Schleuse_MultiSensor "UG Schleuse BMS" @ "UG" [ id= "26.CAC687010000", refresh = 60, lightsensor = false, temperaturesensor="DS2438" ] {
        Channels:
          Type temperature-por-res : temperature [ ignorepor=false, resolution="11" ]
          Type humidity         : humidity         [  ]
          Type absolutehumidity : absolutehumidity [  ]
          Type dewpoint         : dewpoint         [  ]
          Type supplyvoltage    : supplyvoltage    [  ]
      }

      Thing basic UG_Schleuse_TempSensor "UG Schleuse Temp Sensor (on BMS)" @ "UG" [ id="28.3755CF040000", temperaturesensor="DS18B20", refresh = 60 ] {
          Channels:
            Type temperature-por-res : temperature  [ ignorepor=false, resolution="12" ]
      }

      /*
        ****************** Bus 1 --> Busmaster 81.43D135000000, Number 1
        ****************** Devices
      */
      // NO DEVICES

      /************* OWServer sensix */
      Channels:
        /************* Overall */
        Type owfs-number : OW_All_Errors_CRC8     "CRC8 Errors"             [ path="statistics/errors/CRC8_errors", refresh = 60 ]
        Type owfs-number : ow_test            "UG Schleuse Temp (via path)" [ path="28.3755CF040000/temperature12", refresh = 60 ]
        /************* Bus 0 */
        Type owfs-number : OW_Bus0_Errors_General "General Errors"          [ path="bus.0/bus.0/interface/statistics/errors", refresh = 60 ]
        Type owfs-number : OW_Bus0_Errors_Reset   "Reset Errors"            [ path="bus.0/bus.0/interface/statistics/reset_errors", refresh = 60 ]
        Type owfs-number : OW_Bus0_Errors_Read    "Read Errors"             [ path="bus.0/bus.0/interface/statistics/read_errors", refresh = 60 ]
        Type owfs-number : OW_Bus0_Errors_Search1 "Search Errors (pass 1)"  [ path="bus.0/bus.0/interface/statistics/search_errors/error_pass_1", refresh = 60 ]
        Type owfs-number : OW_Bus0_Reconnects     "Reconnects"              [ path="bus.0/bus.0/interface/statistics/reconnects", refresh = 60 ]
        Type owfs-number : OW_Bus0_BusTime        "Bus Time"                [ path="bus.0/bus.0/interface/statistics/bus_time", refresh = 60 ]
        Type owfs-number : OW_Bus0_ElapsedTime    "Elapsed Time"            [ path="bus.0/bus.0/interface/statistics/elapsed_time", refresh = 60 ]

        
        /************* Bus 1 */
        Type owfs-number : OW_Bus1_Errors_General "General Errors"          [ path="bus.0/bus.1/interface/statistics/errors", refresh = 60 ]
        Type owfs-number : OW_Bus1_Errors_Reset   "Reset Errors"            [ path="bus.0/bus.1/interface/statistics/reset_errors", refresh = 60 ]
        Type owfs-number : OW_Bus1_Errors_Read    "Read Errors"             [ path="bus.0/bus.1/interface/statistics/read_errors", refresh = 60 ]
        Type owfs-number : OW_Bus1_Errors_Search1 "Search Errors (pass 1)"  [ path="bus.0/bus.1/interface/statistics/search_errors/error_pass_1", refresh = 60 ]
        Type owfs-number : OW_Bus1_Reconnects     "Reconnects"              [ path="bus.0/bus.1/interface/statistics/reconnects", refresh = 60 ]
        Type owfs-number : OW_Bus1_BusTime        "Bus Time"                [ path="bus.0/bus.1/interface/statistics/bus_time", refresh = 60 ]
        Type owfs-number : OW_Bus1_ElapsedTime    "Elapsed Time"            [ path="bus.0/bus.1/interface/statistics/elapsed_time", refresh = 60 ]
    }

For the OW_Bus0* and OW_Bus1* channels, I get the following log output when logging at trace level:

2020-02-12 22:57:53.736 [TRACE] [internal.owserver.OwserverConnection] - owServerConnection already open, skipping input buffer
2020-02-12 22:57:53.737 [TRACE] [internal.owserver.OwserverConnection] - wrote: messageType READ, size 44, controlFlags 0x00000104, payload '/system/process/pid'
2020-02-12 22:57:53.739 [TRACE] [internal.owserver.OwserverConnection] - read: return code 12, size 36, controlFlags 0x00000104, payload '        1567'
2020-02-12 22:57:53.741 [DEBUG] [internal.owserver.OwserverConnection] - read pid 1567 -> connection still alive
2020-02-12 22:57:53.742 [DEBUG] [internal.owserver.OwserverConnection] - failed requesting messageType READ, size 64, controlFlags 0x00000104, payload 'bus.0/bus.1/interface/statistics/errors'->return code -1, size 24, controlFlags 0x00000104, payload '' [I/O error: exception while reading packet - Read timed out]
2020-02-12 22:57:53.743 [DEBUG] [ternal.handler.OwserverBridgeHandler] - could not read direct channel onewire:owserver:sensix:OW_Bus1_Errors_General: I/O error: exception while reading packet - Read timed out
2020-02-12 22:57:53.747 [TRACE] [internal.owserver.OwserverConnection] - owServerConnection already open, skipping input buffer
2020-02-12 22:57:53.750 [TRACE] [internal.owserver.OwserverConnection] - wrote: messageType READ, size 70, controlFlags 0x00000104, payload 'bus.0/bus.1/interface/statistics/reset_errors'
2020-02-12 22:57:53.752 [TRACE] [internal.owserver.OwserverConnection] - read: return code -1, size 24, controlFlags 0x00000104, payload ''
2020-02-12 22:57:56.757 [TRACE] [internal.owserver.OwserverConnection] - owServerConnection already open, skipping input buffer
2020-02-12 22:57:56.759 [TRACE] [internal.owserver.OwserverConnection] - wrote: messageType READ, size 44, controlFlags 0x00000104, payload '/system/process/pid'
2020-02-12 22:57:56.760 [TRACE] [internal.owserver.OwserverConnection] - read: return code 12, size 36, controlFlags 0x00000104, payload '        1567'
2020-02-12 22:57:56.761 [DEBUG] [internal.owserver.OwserverConnection] - read pid 1567 -> connection still alive
2020-02-12 22:57:56.762 [DEBUG] [internal.owserver.OwserverConnection] - failed requesting messageType READ, size 70, controlFlags 0x00000104, payload 'bus.0/bus.1/interface/statistics/reset_errors'->return code -1, size 24, controlFlags 0x00000104, payload '' [I/O error: exception while reading packet - Read timed out]
2020-02-12 22:57:56.763 [DEBUG] [ternal.handler.OwserverBridgeHandler] - could not read direct channel onewire:owserver:sensix:OW_Bus1_Errors_Reset: I/O error: exception while reading packet - Read timed out
2020-02-12 22:57:56.793 [TRACE] [internal.owserver.OwserverConnection] - owServerConnection already open, skipping input buffer
2020-02-12 22:57:56.795 [TRACE] [internal.owserver.OwserverConnection] - wrote: messageType READ, size 69, controlFlags 0x00000104, payload 'bus.0/bus.1/interface/statistics/read_errors'
2020-02-12 22:57:56.796 [TRACE] [internal.owserver.OwserverConnection] - read: return code -1, size 24, controlFlags 0x00000104, payload ''
2020-02-12 22:57:59.803 [TRACE] [internal.owserver.OwserverConnection] - owServerConnection already open, skipping input buffer
2020-02-12 22:57:59.805 [TRACE] [internal.owserver.OwserverConnection] - wrote: messageType READ, size 44, controlFlags 0x00000104, payload '/system/process/pid'
2020-02-12 22:57:59.806 [TRACE] [internal.owserver.OwserverConnection] - read: return code 12, size 36, controlFlags 0x00000104, payload '        1567'
2020-02-12 22:57:59.807 [DEBUG] [internal.owserver.OwserverConnection] - read pid 1567 -> connection still alive
2020-02-12 22:57:59.808 [DEBUG] [internal.owserver.OwserverConnection] - failed requesting messageType READ, size 69, controlFlags 0x00000104, payload 'bus.0/bus.1/interface/statistics/read_errors'->return code -1, size 24, controlFlags 0x00000104, payload '' [I/O error: exception while reading packet - Read timed out]
2020-02-12 22:57:59.809 [DEBUG] [ternal.handler.OwserverBridgeHandler] - could not read direct channel onewire:owserver:sensix:OW_Bus1_Errors_Read: I/O error: exception while reading packet - Read timed out
2020-02-12 22:57:59.810 [TRACE] [internal.owserver.OwserverConnection] - owServerConnection already open, skipping input buffer
2020-02-12 22:57:59.811 [TRACE] [internal.owserver.OwserverConnection] - wrote: messageType READ, size 84, controlFlags 0x00000104, payload 'bus.0/bus.1/interface/statistics/search_errors/error_pass_1'
2020-02-12 22:57:59.892 [TRACE] [internal.owserver.OwserverConnection] - read: return code -1, size 24, controlFlags 0x00000104, payload ''
2020-02-12 22:58:02.896 [TRACE] [internal.owserver.OwserverConnection] - owServerConnection already open, skipping input buffer
2020-02-12 22:58:02.897 [TRACE] [internal.owserver.OwserverConnection] - wrote: messageType READ, size 44, controlFlags 0x00000104, payload '/system/process/pid'
2020-02-12 22:58:02.899 [TRACE] [internal.owserver.OwserverConnection] - read: return code 12, size 36, controlFlags 0x00000104, payload '        1567'
2020-02-12 22:58:02.900 [DEBUG] [internal.owserver.OwserverConnection] - read pid 1567 -> connection still alive
2020-02-12 22:58:02.901 [DEBUG] [internal.owserver.OwserverConnection] - failed requesting messageType READ, size 84, controlFlags 0x00000104, payload 'bus.0/bus.1/interface/statistics/search_errors/error_pass_1'->return code -1, size 24, controlFlags 0x00000104, payload '' [I/O error: exception while reading packet - Read timed out]
2020-02-12 22:58:02.902 [DEBUG] [ternal.handler.OwserverBridgeHandler] - could not read direct channel onewire:owserver:sensix:OW_Bus1_Errors_Search1: I/O error: exception while reading packet - Read timed out

But when looking via owhttp, I see what I want to have:

Any hints???
Thanks!!!
Best Regards,
Alex

J-N-K · February 14, 2020, 6:21am

You show bus.0/bus.0. but the log says bus.0/bus.1

Fuzzy · February 14, 2020, 9:56am

Hi Jan,
sorry - I just copied out that part of the log without checking that the image below showed it. It is the same for both buses. Both are (with respect to these statistics) configured the same way in the things (see my first post).

And here’s the screenshot for owhttp of bus1…

Thanks.

Fuzzy · February 14, 2020, 12:58pm

New idea … new discoveries…

I started owserver in debug mode and found out that when I access e.g. bus_time via owhttp, it receives a slightly shortened path:

  DEBUG: handler.c:(153) START handler /bus.1/interface/statistics/bus_time
   CALL: data.c:(103) DataHandler: parse path=/bus.1/interface/statistics/bus_time
  DEBUG: ow_parseobject.c:(163) /bus.1/interface/statistics/bus_time
   CALL: ow_parsename.c:(104) path=[/bus.1/interface/statistics/bus_time]
  DEBUG: ow_regex.c:(201) 0: 0->5 found <><bus.1><>
  DEBUG: ow_regex.c:(201) 1: 4->5 found <bus.><1><>
  DEBUG: ow_regex.c:(201) 0: 0->7 found <></bus.1/><interface/statistics/bus_time>
  DEBUG: ow_regex.c:(154) Not found
  DEBUG: ow_regex.c:(154) Not found
   CALL: data.c:(144) Read message
  DEBUG: read.c:(55) ReadHandler start
  DEBUG: read.c:(61) ReadHandler: From Client sm->payload=37 sm->size=12 sm->offset=0
  DEBUG: read.c:(79) ReadHandler: call FS_read_postparse on /bus.1/interface/statistics/bus_time
  DEBUG: ow_read.c:(72) /bus.1/interface/statistics/bus_time
  DEBUG: ow_read.c:(333) file_length=12 offset=0 size=12
  DEBUG: ow_read.c:(620) Read /bus.1/interface/statistics/bus_time Extension 0 Gives result 0

… as opposed to when openhab queries it (note - I grabbed another item that was at hand, not bus_time but at same level) with above configuration:

  DEBUG: handler.c:(153) START handler /bus.0/bus.0/interface/statistics/read_errors
   CALL: data.c:(103) DataHandler: parse path=/bus.0/bus.0/interface/statistics/read_errors
  DEBUG: ow_parseobject.c:(163) /bus.0/bus.0/interface/statistics/read_errors
   CALL: ow_parsename.c:(104) path=[/bus.0/bus.0/interface/statistics/read_errors]
  DEBUG: ow_regex.c:(201) 0: 0->5 found <><bus.0><>
  DEBUG: ow_regex.c:(201) 1: 4->5 found <bus.><0><>
  DEBUG: ow_regex.c:(201) 0: 0->7 found <></bus.0/><bus.0/interface/statistics/read_errors>
  DEBUG: ow_regex.c:(201) 0: 0->5 found <><bus.0><>
  DEBUG: ow_regex.c:(201) 1: 4->5 found <bus.><0><>
  DEBUG: ow_parsename.c:(164) Set error to 27 <Path - bad path syntax>
  DEBUG: ow_parsename.c:(63) /bus.0/bus.0/interface/statistics/read_errors
  DEBUG: data.c:(106) DataHandler: OWQ_create failed cm.ret=-1
  DEBUG: data.c:(207) DataHandler: cm.ret=-1
  DEBUG: to_client.c:(76) payload=0 size=0, ret=-1, sg=0x104 offset=0
  DEBUG: to_client.c:(85) No data
  DEBUG: data.c:(226) Finished with client request

I then adjusted the thing.config by removing the leading “bus.0” shown in the owhttpd screenshot…

        /************* Bus 0 */
        Type owfs-number : OW_Bus0_Errors_General "General Errors"          [ path="bus.0/interface/statistics/errors", refresh = 60 ]
        Type owfs-number : OW_Bus0_Errors_Reset   "Reset Errors"            [ path="bus.0/interface/statistics/reset_errors", refresh = 60 ]
        Type owfs-number : OW_Bus0_Errors_Read    "Read Errors"             [ path="bus.0/interface/statistics/read_errors", refresh = 60 ]
        Type owfs-number : OW_Bus0_Errors_Search1 "Search Errors (pass 1)"  [ path="bus.0/interface/statistics/search_errors/error_pass_1", refresh = 60 ]
        Type owfs-number : OW_Bus0_Reconnects     "Reconnects"              [ path="/bus.0/interface/statistics/reconnects", refresh = 60 ]
        Type owfs-number : OW_Bus0_BusTime        "Bus Time"                [ path="/bus.0/interface/statistics/bus_time", refresh = 60 ]
        Type owfs-number : OW_Bus0_ElapsedTime    "Elapsed Time"            [ path="/bus.0/interface/statistics/elapsed_time", refresh = 60 ]
        
        /************* Bus 1 */
        Type owfs-number : OW_Bus1_Errors_General "General Errors"          [ path="/bus.1/interface/statistics/errors", refresh = 60 ]
        Type owfs-number : OW_Bus1_Errors_Reset   "Reset Errors"            [ path="/bus.1/interface/statistics/reset_errors", refresh = 60 ]
        Type owfs-number : OW_Bus1_Errors_Read    "Read Errors"             [ path="/bus.1/interface/statistics/read_errors", refresh = 60 ]
        Type owfs-number : OW_Bus1_Errors_Search1 "Search Errors (pass 1)"  [ path="/bus.1/interface/statistics/search_errors/error_pass_1", refresh = 60 ]
        Type owfs-number : OW_Bus1_Reconnects     "Reconnects"              [ path="bus.1/interface/statistics/reconnects", refresh = 60 ]
        Type owfs-number : OW_Bus1_BusTime        "Bus Time"                [ path="bus.1/interface/statistics/bus_time", refresh = 60 ]
        Type owfs-number : OW_Bus1_ElapsedTime    "Elapsed Time"            [ path="bus.1/interface/statistics/elapsed_time", refresh = 60 ]

… et voila - it works . Even with or without leading slash.

Two more things, I noticed though…

- When owserver goes down (and then up again), openhab stops querying / updating… I have to restart OH in order to get the updates running again. I can reproduce by killing the owserver process, waiting ~ a minute and the do a restart of it.

- And when I do changes on the things file for OneWire, it’s likely that I have to restart openhab so it picks up the changes. For example, I changed the naming of two channels (0->A, 1->B) and minutes later, it is still being updated on the old name (but also on the new name…):

Any advice on how to proceed with these?

Thanks.
BR,
Alex
I also noticed that during debugging for above issue - in order to get rid of the leading “bus.0” in the path config of the onewire thing, I head to restart openhab.

J-N-K · February 14, 2020, 6:11pm

For the second: don’t use things-files. I have never experienced these changes-not-picked-up with UI configured things.

The other one: probably a bug. Will check that. If I don‘t report back within a week, please ping me. I‘m quite busy ATM.

J-N-K · February 15, 2020, 3:03pm

Is your openHAB instance running under windows or linux? I can reproduce the problem with the latest openhab 2.5.2 SNAPSHOT under Windows with Java 11, but not in my production system running OH Snapshot #1758 and Java 8.

Fuzzy · February 15, 2020, 10:31pm

Thanks for your efforts Jan.
I’m running OH in a debian VM which is hosted by QNAP Container Station. The OWServer is running in such a debian VM as well:
Linux 4.14.24-qnap #1 SMP Fri Dec 6 11:32:48 CST 2019 x86_64 GNU/Linux
cat /etc/issue --> Debian GNU/Linux 9 \n \l

OH’s starting page tells me “openHAB 2.5.0 Release Build”
Java version: zulu-8/azulsystems,now 8.44.0.11 amd64

hope this helps.

Fuzzy · March 11, 2020, 11:01pm

Hi all,

I did some further tracing and thinking. Details posted in a for this topic created issue: https://github.com/openhab/openhab-addons/issues/7149.

Fuzzy · May 2, 2020, 9:34pm

Hi all, @J-N-K,

I prepared a fix, as described in https://github.com/openhab/openhab-addons/issues/7149.
Pull request is under way…

Fuzzy · May 12, 2020, 10:55pm

Hi all,

I dug a bit deeper as described in above mentioned issue.
PR is here… https://github.com/openhab/openhab-addons/pull/7621.

Fuzzy · May 16, 2020, 7:49pm

PR just got merged - part of openHAB Milestone 2.5.5 - thanks for the support J-N-K!