OWX_ASYNC: Regelmäßig Disconnect

sledge · 11 April 2018, 17:28:19

Hi,

seit einiger Zeit betreibe ich auf meinem 1-Wire Bus sowohl einen Temperatursensor als auch einen Counter DS2423 auf Attiny-Basis - das klappt soweit auch recht zufriedenstellend.

Beim Durchsehen der Logdateien ist mir aufgefallen, dass mit Regelmäßigkeit alle 130-135 Sekunden folgendes geschieht:

Code Auswählen

2018.04.11 16:56:52 3: OWX_ASYNC_Disconnect
2018.04.11 16:59:06 3: OWX_ASYNC_Disconnect
2018.04.11 17:01:21 3: OWX_ASYNC_Disconnect
2018.04.11 17:03:35 3: OWX_ASYNC_Disconnect
2018.04.11 17:05:50 3: OWX_ASYNC_Disconnect
2018.04.11 17:08:04 3: OWX_ASYNC_Disconnect
2018.04.11 17:10:17 3: OWX_ASYNC_Disconnect

Ich habe das dann über einen gewissen Zeitraum beobachtet und mit apptime und freezemon auf wiederkehrende Prozesse / Timer überprüft, die ungefähr ebenfalls 25-27 Mal je Stunde auftreten. Bisher Fehlanzeige.

Also das Logging auf verbose=5 hochgedreht - und leider auch nicht schlauer geworden. global verbose = 3 - einen Auszug mit verbose = 5 kann ich auch beisteuern, der hat mE aber keine weitere Information mitgeliefert.

Hier ein Auszug zweier solcher Disconnects mit verbose=5 für alle 1-Wire Geräte:

Code Auswählen


2018.04.11 16:54:39 3: OWX_ASYNC_Disconnect
2018.04.11 16:54:39 1: 192.168.0.34:8899 disconnected, waiting to reappear (1wire.wlan)
2018.04.11 16:54:39 5: OWX_ASYNC_Set request 1wire.wlan FF ?
2018.04.11 16:54:39 1: 192.168.0.34:8899 reappeared (1wire.wlan)
2018.04.11 16:54:39 5: OWX_ASYNC_Set request 1wire.wlan FF ?
2018.04.11 16:54:39 5: SW: c1
2018.04.11 16:54:39 5: SW: 17455b0f91
2018.04.11 16:54:39 5: OWX_DS2480 read: After loop no. 1 received: 17455b0f91
2018.04.11 16:54:39 3: OWX_SER::Detect 1-Wire bus 1wire.wlan: interface master DS2480 re-detected
2018.04.11 16:54:39 5: OWX_ASYNC_Schedule master: 1wire.wlan, task: 1wire.wlan
2018.04.11 16:54:50 5: SW: e3c5
2018.04.11 16:54:50 5: SW: e1f0e3b5
2018.04.11 16:54:50 5: SW: e100000000000000000000000000000000e3a5
2018.04.11 16:54:50 5: OWX_ASYNC_Schedule master: 1wire.wlan, task: WK.KG.1WC
2018.04.11 16:54:50 5: OWX_ASYNC_Schedule master: 1wire.wlan, task: WK.KG.1WC
2018.04.11 16:54:50 5: OWX_ASYNC_Schedule master: 1wire.wlan, task: WK.KG.1WT
2018.04.11 16:54:50 5: OWX_DS2480 read: After loop no. 2 received: cdf08108aaaa88a2828a0082280220002888
2018.04.11 16:54:50 5: OWX_SER::Search: new device found 28.FFDAB9901604.A6
2018.04.11 16:54:50 5: SW: e3c5
2018.04.11 16:54:50 5: SW: e1f0e3b5
2018.04.11 16:54:50 5: SW: e102000000000000000000000000000000e3a5
2018.04.11 16:54:50 5: OWX_DS2480 read: After loop no. 3 received: cdf0a302088800000000000000000800a220
2018.04.11 16:54:50 5: OWX_SER::Search: new device found 1D.A20000000002.4D
2018.04.11 16:54:50 5: SW: e3c5
2018.04.11 16:54:50 5: SW: e1f0e3b5
2018.04.11 16:54:50 5: SW: e102000000000000000000000000000000e3a5
2018.04.11 16:54:50 5: OWX_DS2480 read: After loop no. 3 received: cdf0a302088800000000000000000800a220
2018.04.11 16:54:50 2: OWX: 1-Wire devices found on bus 1wire.wlan (WK.KG.1WT,WK.KG.1WC)
2018.04.11 16:54:50 4: OWX_ASYNC_RunTasks: 1wire.wlan task exited: OWX: 1-Wire devices found on bus 1wire.wlan 
28.FFDAB9901604      DS18B20        WK.KG.1WT
1D.A20000000002      DS2423         WK.KG.1WC

2018.04.11 16:54:51 5: SW: e3c5
2018.04.11 16:54:51 5: SW: e15528ffdab9901604a644
2018.04.11 16:54:51 5: OWX_DS2480 read: After loop no. 2 received: cd5528ffdab9901604a644
2018.04.11 16:54:51 5: SW: e3c5
2018.04.11 16:54:51 5: SW: e1551da200000000024da5c001ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
2018.04.11 16:54:51 5: OWX_DS2480 read: After loop no. 2 received: cd551da200000000024da5c001323031382d30342d3130206d69646e6967687420202034332e303020202020202b00000000000000e69f
2018.04.11 16:54:51 5: SW: e3c5
2018.04.11 16:54:51 5: OWX_DS2480 read: After loop no. 1 received: cd
2018.04.11 16:54:51 5: OWX_ASYNC_RunTasks: WK.KG.1WC task finished
2018.04.11 16:54:51 5: SW: e3c5
2018.04.11 16:54:51 5: SW: e1551da200000000024da5e001ffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffffff
2018.04.11 16:54:51 5: OWX_DS2480 read: After loop no. 2 received: cd551da200000000024da5e001323031382d30342d3130206d69646e6967687420202020342e313720202020208c070000000000004a5c
2018.04.11 16:54:52 5: SW: e3c5
2018.04.11 16:54:52 5: OWX_DS2480 read: After loop no. 1 received: cd
2018.04.11 16:54:52 5: OWX_ASYNC_RunTasks: WK.KG.1WC task finished
2018.04.11 16:54:52 5: SW: e3c5
2018.04.11 16:54:52 5: SW: e15528ffdab9901604a6beffffffffffffffffff
2018.04.11 16:54:52 5: OWX_DS2480 read: After loop no. 2 received: cd5528ffdab9901604a6beed00140c7ffffffffd
2018.04.11 16:54:52 5: OWX_ASYNC_RunTasks: WK.KG.1WT task finished
2018.04.11 16:56:52 3: OWX_ASYNC_Disconnect
2018.04.11 16:56:52 1: 192.168.0.34:8899 disconnected, waiting to reappear (1wire.wlan)
2018.04.11 16:56:52 5: OWX_ASYNC_Set request 1wire.wlan FF ?
2018.04.11 16:56:52 1: 192.168.0.34:8899 reappeared (1wire.wlan)
2018.04.11 16:56:52 5: OWX_ASYNC_Set request 1wire.wlan FF ?
2018.04.11 16:56:52 5: SW: c1
2018.04.11 16:56:52 5: SW: 17455b0f91
2018.04.11 16:56:52 5: OWX_DS2480 read: After loop no. 1 received: 17455b0f91
2018.04.11 16:56:52 3: OWX_SER::Detect 1-Wire bus 1wire.wlan: interface master DS2480 re-detected
2018.04.11 16:56:52 5: OWX_ASYNC_Schedule master: 1wire.wlan, task: 1wire.wlan

Hier noch ein List der Geräte:

Code Auswählen

Internals:
   ALARMED    no
   CFGFN      
   DEF        192.168.0.34:8899
   DeviceName 192.168.0.34:8899
   FD         20
   INTERFACE  DS2480
   NAME       1wire.wlan
   NOTIFYDEV  global
   NR         403
   NTFY_ORDER 50-1wire.wlan
   NUMTASKS   0
   PARTIAL    
   PRESENT    1
   ROM_ID     FF
   STATE      Active
   TIMEOUTS   0
   TYPE       OWX_ASYNC
   followAlarms off
   interval   300
   ALARMDEVS:
   DEVS:
   READINGS:
     2018-04-11 17:19:14   state           opened
   helper:
     bm:
       OWX_ASYNC_Attr:
         cnt        6
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        11.04. 16:48:56
         max        9.89437103271484e-05
         tot        0.00042271614074707
         mAr:
           set
           1wire.wlan
           maxtimeouts
           100
       OWX_ASYNC_Get:
         cnt        20
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        11.04. 16:21:16
         max        6.98566436767578e-05
         tot        0.00096893310546875
         mAr:
           HASH(0x558d33605f98)
           1wire.wlan
           ?
       OWX_ASYNC_Notify:
         cnt        12
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        11.04. 16:39:24
         max        0.000195980072021484
         tot        0.00113081932067871
         mAr:
           HASH(0x558d33605f98)
           HASH(0x558d2dcf1860)
       OWX_ASYNC_Read:
         cnt        894
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        11.04. 16:57:04
         max        0.210882186889648
         tot        59.2463135719299
         mAr:
           HASH(0x558d33605f98)
       OWX_ASYNC_Ready:
         cnt        94
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        11.04. 16:21:30
         max        1.2957170009613
         tot        20.88170170784
         mAr:
           HASH(0x558d33605f98)
       OWX_ASYNC_Set:
         cnt        131
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        11.04. 16:24:20
         max        0.000936031341552734
         tot        0.0331518650054932
         mAr:
           HASH(0x558d33605f98)
           1wire.wlan
           ?
   tasks:
Attributes:
   buspower   real
   devStateIcon Active:10px-kreis-gruen disconnected:10px-kreis-rot
   room       1wire,system->Interfaces
   verbose    5

Code Auswählen

Internals:
   ASYNC      1
   CFGFN      
   DEF        DS2423 A20000000002
   ERRCOUNT   1
   INTERVAL   300
   IODev      1wire.wlan
   NAME       WK.KG.1WC
   NOTIFYDEV  global
   NR         526
   NTFY_ORDER 50-WK.KG.1WC
   NUMTASKS   0
   OW_FAMILY  1D
   OW_ID      A20000000002
   PRESENT    0
   ROM_ID     1D.A20000000002.4D
   STATE      A: 43.00  cts A_r:  0.00  cts/h Wasseruhr: 4.322  m^3 Liter/h: 0.027  m^3/h
   TYPE       OWCOUNT
   DATA:
     memory     2018-04-10 midnight    4.17     
   Helper:
     DBLOG:
       Wasseruhr:
         dblog:
           TIME       1523459967.62056
           VALUE      4.3225
   READINGS:
     2018-04-11 17:19:27   A               43
     2018-04-11 17:19:27   A_rate          0
     2018-04-11 17:19:27   Wasseruhr       4.3225
     2018-04-11 17:19:27   lit/h           0.0271
     2018-04-11 17:19:27   memory          2018-04-10 midnight    4.17     
     2018-04-11 17:21:29   present         0
     2018-04-11 17:19:27   state           A: 43.00  cts A_r:  0.00  cts/h Wasseruhr: 4.322  m^3 Liter/h: 0.027  m^3/h
   helper:
     bm:
       OWCOUNT_Attr:
         cnt        2
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        11.04. 16:08:44
         max        0.000123977661132812
         tot        0.000185012817382812
         mAr:
           set
           WK.KG.1WC
           verbose
           5
       OWCOUNT_Get:
         cnt        8
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        11.04. 16:08:35
         max        8.10623168945312e-05
         tot        0.000572919845581055
         mAr:
           HASH(0x558d34937af8)
           WK.KG.1WC
           ?
       OWCOUNT_Init:
         cnt        48
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        11.04. 15:47:59
         max        0.0013129711151123
         tot        0.0516750812530518
         mAr:
           HASH(WK.KG.1WC)
       OWCOUNT_Notify:
         cnt        12
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        11.04. 16:13:00
         max        9.01222229003906e-05
         tot        0.000519990921020508
         mAr:
           HASH(0x558d34937af8)
           HASH(0x558d2dcf1860)
       OWCOUNT_Set:
         cnt        83
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        11.04. 16:24:20
         max        0.000236988067626953
         tot        0.00420904159545898
         mAr:
           HASH(0x558d34937af8)
           WK.KG.1WC
           ?
   owg_midnight:
     43
     4.17
   owg_str:
     
     
     undef
     undef
     undef
     undef
     undef
     undef
     undef
     undef
     undef
     undef
     undef
     undef
     2018-04-10 midnight   43.00     
     2018-04-10 midnight    4.17     
   owg_val:
     43
     1951
Attributes:
   BFactor    0.001
   BMode      normal
   BName      Wasseruhr
   BOffset    2371.5
   BRate      lit/h|Liter/h
   BUnit      m^3
   DbLogInclude Wasseruhr
   IODev      1wire.wlan
   icon       sani_water_tap
   model      DS2423enew
   room       1wire

Code Auswählen

Internals:
   ALARM      0
   ASYNC      1
   CFGFN      
   DEF        DS18B20 FFDAB9901604
   ERRCOUNT   0
   INTERVAL   300
   IODev      1wire.wlan
   NAME       WK.KG.1WT
   NOTIFYDEV  global
   NR         452
   NTFY_ORDER 50-WK.KG.1WT
   NUMTASKS   0
   OW_FAMILY  28
   OW_ID      FFDAB9901604
   PRESENT    1
   ROM_ID     28.FFDAB9901604.A6
   STATE      T: 14.81 °C
   TYPE       OWTHERM
   owg_temp   14.8125
   owg_th     20
   owg_tl     12
   READINGS:
     2018-04-11 17:21:41   present         1
     2018-04-11 17:21:43   state           T: 14.81 °C
     2018-04-11 17:21:43   temperature     14.8125
   helper:
     bm:
       OWTHERM_Attr:
         cnt        2
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        11.04. 16:09:09
         max        0.000123977661132812
         tot        0.000242948532104492
         mAr:
           set
           WK.KG.1WT
           verbose
           5
       OWTHERM_Get:
         cnt        6
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        11.04. 16:39:24
         max        0.000128984451293945
         tot        0.000519037246704102
         mAr:
           HASH(0x558d341ffe50)
           WK.KG.1WT
           ?
       OWTHERM_Init:
         cnt        48
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        11.04. 16:37:15
         max        0.00108003616333008
         tot        0.0393931865692139
         mAr:
           HASH(0x558d341ffe50)
       OWTHERM_Notify:
         cnt        12
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        11.04. 16:23:56
         max        4.00543212890625e-05
         tot        0.000356674194335938
         mAr:
           HASH(0x558d341ffe50)
           HASH(0x558d2dcf1860)
       OWTHERM_Set:
         cnt        39
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        11.04. 16:24:20
         max        0.00020599365234375
         tot        0.00180339813232422
         mAr:
           HASH(0x558d341ffe50)
           WK.KG.1WT
           ?
   tempf:
     factor     1
     offset     0
Attributes:
   IODev      1wire.wlan
   icon       temp_temperature
   model      DS18B20
   room       1wire
   tempHigh   20
   tempLow    12

Bisher stört mich das Verhalten nicht, da ich nur meine Wasseruhr auslese (deren Werte ja zwischengepuffert werden) und einen Temperaturfühler an dem System betreibe - aber in Zukunft wollte ich auch via 1-Wire schalten - und da hätte ich es schon gerne sauber.

Freue mich über jede Anregung, das Problem einzukreisen.

Gruß,
Tom

Tom Major · 11 April 2018, 19:28:59

Um welche DS2480 Hardware handelt es sich und wo hängt die genau dran?

sledge · 11 April 2018, 19:33:42

Es handelt sich um einen1-Wire-USB-WLAN Adapter von locutus, der auch über WLAN betrieben wird: https://forum.fhem.de/index.php/topic,57559.0.html

Wenn ich den Ursprung des Threads richtig deute, ist das hier verbaut https://forum.fhem.de/index.php/topic,18996.msg489913.html#msg489913:

ZitatDie Eckdaten:
DS2480B Serial 1-Wire Line Driver
FT230XS USB UART Interface IC
DS9503 ESD Protection Diode
USB Typ A Stecker
3-pol. WAGO Klemme mit Betätigungsdrücker

Tom Major · 11 April 2018, 19:38:18

interessantes Device, kannte ich noch nicht.
Könnte es nicht ein simples WLAN disconnect sein?

Code Auswählen

2018.04.11 16:54:39 1: 192.168.0.34:8899 disconnected, waiting to reappear (1wire.wlan)

sledge · 11 April 2018, 19:48:29

Zitat von: Tom Major am 11 April 2018, 19:38:18
interessantes Device, kannte ich noch nicht.
Könnte es nicht ein simples WLAN disconnect sein?
Code Auswählen Erweitern
2018.04.11 16:54:39 1: 192.168.0.34:8899 disconnected, waiting to reappear (1wire.wlan)

Könnte sicherlich, aber die Regelmäßigkeit verwundert mich - und signaltechnisch sollte der Standort ok sein - hatte es mit dem Mobiltelefon und einem WIFI-Checker vorher "ausgemessen".

Zudem: Wenn ich parallel zu einem "disconnect" in der Weboberfläche des USR-WIFI232-T hin und her springe, merke ich von dem "disconnect" gar nichts. Und ein WLAN-Disconnect müsste man doch dort spüren?

Und ja: Interessantes Device. Und wie gesagt: Es ist die absolute Regelmäßigkeit von 135 Sekunden, die mE gegen ein einfaches "WLAN ist mal weg, WLAN ist wieder da" spricht. Andere Geräte in dem gleichen WLAN haben das Problem nicht.

Tom Major · 11 April 2018, 19:55:18

Zitat von: sledge am 11 April 2018, 19:48:29
Könnte sicherlich, aber die Regelmäßigkeit verwundert mich - und signaltechnisch sollte der Standort ok sein - hatte es mit dem Mobiltelefon und einem WIFI-Checker vorher "ausgemessen".

Zudem: Wenn ich parallel zu einem "disconnect" in der Weboberfläche des USR-WIFI232-T hin und her springe, merke ich von dem "disconnect" gar nichts. Und ein WLAN-Disconnect müsste man doch dort spüren?

Und ja: Interessantes Device. Und wie gesagt: Es ist die absolute Regelmäßigkeit von 135 Sekunden, die mE gegen ein einfaches "WLAN ist mal weg, WLAN ist wieder da" spricht. Andere Geräte in dem gleichen WLAN haben das Problem nicht.

Ich wollte damit nur sagen falls es ein WLAN disconnect sein könnte muss man natürlich auch jenseits von 1-wire suchen.

Wenn ich den log richtig deute passiert das disconnect und reconnect alles innerhalb einer Sekunde? Eventuell merkt man solch ein schnelles reconnect nicht in der Weboberfläche, aber für das OWX_ASYNC könnte (ab und zu) ein timeout zuschlagen. Die timeouts in OWX_ASYNC würde ich mir als erstes ansehen.

sledge · 11 April 2018, 20:10:02

Hi,

dem Hinweis folgend werde ich jetzt mal Stück für Stück meine WLAN-Infrastruktur durchchekcen - die hat bis jetzt zwar noch nie Probleme gemacht, aber vielleicht fängt es ja so an ;-/

Danke in jedem Fall... nach wie vor für Hinweise dankbar.

Tom Major · 11 April 2018, 23:58:24

Man könnte z.B. mal in einem script oder so ping Laufzeit Resultate zum USR-WIFI232-T mit entsprechend hoher Frequenz (möglichst mehrmals pro Sekunde) in einen log schreiben lassen und schauen ob im log die 135 Sek. irgendwie zu sehen sind..
Nur so eine Idee um die eine Richtung weiterzuverfolgen, letztendlich kann der Fehler natürlich auch aus einer ganz anderen Ecke kommen

Prof. Dr. Peter Henning · 12 April 2018, 17:41:17

OWX_ASYNC wird nicht mehr gepflegt, und diverse zugehörige Routinen fliegen in absehbarer Zeit aus den OWX-Frontendmodulen heraus.

Ich kann nur raten, stattdessen das aktuelle OWX mit asynchroner Einstellung zu benutzen.

LG

pah

sledge · 12 April 2018, 18:09:22

Zitat von: Prof. Dr. Peter Henning am 12 April 2018, 17:41:17
OWX_ASYNC wird nicht mehr gepflegt, und diverse zugehörige Routinen fliegen in absehbarer Zeit aus den OWX-Frontendmodulen heraus.

Ich kann nur raten, stattdessen das aktuelle OWX mit asynchroner Einstellung zu benutzen.

LG

pah

Danke - dann fang' ich damit mal an ud schaue, ob das Problem ggfs. damit beseitigt ist. Falls nicht, gehe ich der netzwerkseitigen Sollbruchstelle auf den Grund.

VG ThB

sledge · 12 April 2018, 19:00:16

Fast Followup:

Bin auf das OWX-Modul umgestiegen, Devices neu angelegt, log gecheckt: Die Disconnect-Einträge kommen jetzt immer noch, aber "unregelmäßiger" und deutlich seltener.

So richtig kann ich es mir immer noch nicht erklären - alles anderen Devices in dem Raum haben guten Empfang. Dennoch werde ich zwecks Fehlerfindung mal die Fritzbox durch einen anderen WLAN-Geber ersetzen.

Auf verbose=5 entdecke ich jetzt nichts, was mir weitere Hinweise auf den Verursacher liefert - in der letzten halben Stunde 3 Stück.

Damit kann / werde ich erstmal leben, bis ich mir weitere Gedanken über eine IoT-taugliche WLAN- Konfiguration gemacht habe.

Also nicht gelöst, aber bisher schonmal Danke an pah und Tom Major, die mir hier "food for thought" geliefert haben.

VG Tom

Tom Major · 12 April 2018, 19:30:39

Interessanter Test mit dem anderen Modul, es könnte z.B. sein dass es wie gesagt ein WLAN connect Problem ist, aber durch unterschiedliche timeouts in den Modulen OWX_ASYNC und OWX sich der Fehler häufiger bzw. seltener äußert. Eventuell kann man im OWX die timeouts konfigurieren?