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:
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:
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:
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
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
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
Um welche DS2480 Hardware handelt es sich und wo hängt die genau dran?
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 (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 (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
interessantes Device, kannte ich noch nicht.
Könnte es nicht ein simples WLAN disconnect sein?
2018.04.11 16:54:39 1: 192.168.0.34:8899 disconnected, waiting to reappear (1wire.wlan)
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?
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.
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.
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.
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 ;)
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
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
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
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?