Hallo,
ich habe hier ein sehr schwerwiegendes Problem mit einer FHEM-Installation. Zum Aufbau: ich habe eine größere Anzahl an Thermostaten und Wandthermostaten, welche mittels VCCU und einer Reihe von angeschlossenen HMUARTLGWs angesprochen werden. Das ganze beschriebene Problem tritt erst auf, nachdem die Wandthermostate installiert wurden. Nach gut 30-60 Minuten reagiert FHEM nicht mehr und lässt sich weder per telnet, noch per webinterface ansprechen. In den Logs konnte ich dann sehen, dass wohl die queue einiger meiner HMUARTLGWs vollgelaufen ist und ich folgende Nachricht bekomme:
HMUARTLGW 4001_PEQ0531825: queue is full, dropping packetDie Nachricht wird mehr oder weniger gespammt, ist aber kein Vergleich zu dem was kurz darauf folgt:
HMUARTLGW 4001_PEQ0531825: Device not initialized (state: 3, init) but asked to send data. Dropping: As1001B00145FF965C174700050000000000Die Nachricht wird kurz daraufhin mehrere hundert mal pro Sekunde erzeugt und knallt meine Logs nur so zu. Dann reagiert auch FHEM nicht mehr und ich habe nur die Möglichkeit den Prozess zu killen und FHEM neu zu starten. Der beschriebene HMUARTLGW ist hier aber nur ein Beispiel, genauso wie die Nachricht und der state (der ist manchmal auch glaube ich state:2 disconnected). Es tritt auch mit anderen HMUARTLGWs auf. Wichtig ist vielleicht noch, dass dies im Ruhemodus passiert, also ich setze nicht wild irgendwelche Temperaturen oder ähnliches.
Was ich jetzt schon gemacht habe:
- alle HMUARTLGWs auf FW 1.4.1 upgedated
- autoReadReg der Wandthermostate auf off gestellt, um die Last beim Starten niedrig zu halten
- qLen testweise auf 60 und aktuell auf 200 gesetzt
- noch mehr HMUARTLGWs aufgestellt
- FHEM auf aktuelle Version upgedated
Das alles hat nur bewirkt, dass ich den Absturz etwas hinauszögere aber leider nicht unterbinden kann. Ich habe die Vermutung, dass es mit den Wandthermostaten zusammenhängt, da ich auch Installationen besitze, welche ähnlich groß sind aber anstatt Wandthermostate eben normale Thermostate haben und das dort dann nicht auftritt. Die Last eines einzelnen HMUARTLGWs geht kaum über 10% und es tritt trotzdem auf. Meine Fragen wären jetzt:
- Kann ich noch bestimmte Einstellungen in den Wandthermostaten vornehmen, die ich nicht bedacht habe? Die Wandthermostate sind (noch) nicht mit den Thermostaten gepeert
- Kann ich die Größe der aktuellen Queue irgendwie auslesen, damit ich den HMUARTLGW einfach erstmal neustarten kann, damit FHEM zumindest weiterläuft?
- Was kann ich sonst quasi noch tun?
Grüße und Danke
wenn du bei allen devices autoreadreg=0 setzt und keine befehle an die devices sendest, sollte eigentliche ruhe sein.
hat dein system eventuell ein speicherproblem?
gibt es zb "cannot fork" meldungen im fhem.log?
gibt es freezes in fhem? => modul freezemon
was sagt "get hminfo configCheck"?
mit "attr dummy 1" im hauptdevice sollten solche devices in fhem eigentlich komplett stillgelegt werden können. durch entfernen der attribute könntest du dann nach und nach devices wieder "freigeben" und beobachten wo genau das problem liegt.
haben die WT aktuelle fw?
gibt es nachbarn mit homematic, eventuell sogar mit hmip? siehe zb die "unknown device" readings in der vccu.
Speicherproblem kann ich eigentlich ausschließen. Habe wie gesagt einige ähnliche Instanzen und es tritt nur bei vielen Wandthermostaten auf. Teilweise habe ich viel mehr Geräte im Einsatz und es passiert nichts.
Ich habe die logs mal gefiltert nach fork und habe keine Ergebnisse bekommen.
Freezemon hatte ich nicht aktiviert und läuft jetzt, ich werde berichten, wenn sich dort was tut!
Der configcheck wirft viele Geräte raus, wo er noch einige Register nicht lesen konnte und das peering nicht aktiv ist. Ist das sehr problematisch? Ich habe das Auslesen der Register ja erstmal auf off gestellt und vorher ist er mir ja immer abgestürzt, bevor er alles einlesen konnte.
Das mit attr dummy 1 werde ich mir mal merken und mal mit rumspielen. Danke für den Tipp.
Die fw auf den Geräten ist 1.3. Eine neuere gibt es nicht oder? Ansonsten gibt es bei unknown devices schon so 10-15 Stück, das könnten aber noch Austauschgeräte aus der Installation sein. Spielt der Funkverkehr der unbekannten Geräte eine große Rolle? Wenn ja, kann ich ihn irgendwie blockieren? Danke schon mal für die Antwort :)
Hallo,
Zitat von: gritob am 03 Dezember 2018, 11:11:01
HMUARTLGW 4001_PEQ0531825: Device not initialized (state: 3, init) but asked to send data. Dropping: As1001B00145FF965C174700050000000000
Was ist 5C1747? Diese Konfigurationsmessage für dieses Geräts löst das Problem aus.
Was hier passiert ist, dass CUL_HM in einer Endlosschleife diese Message sendet. Die Meldungen von HMUARTLGW sind nur Symptom, nicht Ursache. Ich hatte das auch einmal bisher, konnte es aber nicht reproduzieren und damit auch nicht debuggen...
Kannst Du bitte mal ein List von 5C1747 posten?
Viele Grüße
Michael
Hallo,
ich hab ein gleichgelagertes Problem. Memory oder sonstige Resourcenknappheit am Rechner mit fhem sind ausgeschlossen, allerdings benötigt fhem in dem Zustand dann extrem viel CPU und RAM. Sobald man FHEM beendet/neustartet ist wieder Ruhe für einige Zeit. Das Verhalten kommt aber alle 2-3 Tage wieder.
Bei mir ist es folgende Logzeile:
2018.12.08 12:48:23 1: HMUARTLGW HMLanGW: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B001F100004BD52401050000000001
Im Fehlerfall ca. 150 mal pro Sekunde.
Hier das gewünschte List des Devices:
DEF 4BD524
IODev VCCU
NAME HM_4BD524
NOTIFYDEV global
NR 151
NTFY_ORDER 50-HM_4BD524
STATE CMDs_done
TYPE CUL_HM
channel_01 HM_4BD524_Btn_01
channel_02 HM_4BD524_Btn_02
channel_03 HM_4BD524_Dis
channel_04 HM_4BD524_Key_01
channel_05 HM_4BD524_Key_02
channel_06 HM_4BD524_Key_03
channel_07 HM_4BD524_Key_04
channel_08 HM_4BD524_Key_05
READINGS:
2018-12-08 08:32:22 CommandAccepted yes
2018-09-23 18:12:50 D-firmware 1.2
2018-09-23 18:12:50 D-serialNr NEQ0711879
2018-12-08 08:26:34 PairedTo 0xDEAD11
2016-10-05 04:56:52 R-pairCentral 0xDEAD11
2016-10-05 04:56:52 R-powerSupply bat
2018-12-08 08:26:34 RegL_00. 00:00 02:01 05:80 08:01 0A:DE 0B:AD 0C:11 14:03 21:FF
2018-11-29 18:00:04 aesCommToDev pending
2018-12-08 08:00:08 aesKeyNbr 00
2018-10-05 20:28:48 battery ok
2018-09-23 12:29:42 fwUpdate done
2018-12-08 08:15:08 powerOn 2018-12-08 08:15:08
2018-11-30 17:23:14 sabotageAttackId_ErrIoId_F10000 cnt:18
2018-12-08 04:20:20 sabotageAttack_ErrIoAttack cnt 44
2018-12-08 08:32:22 state CMDs_done
helper:
HM_CMDNR 150
mId 00FB
regLst ,0
rxType 6
expert:
def 1
det 0
raw 1
tpl 0
io:
newChn +4BD524,00,00,00
rxt 0
vccu VCCU
p:
4BD524
00
00
00
prefIO:
HMLanGW
mRssi:
mNo
prt:
bErr 0
sProc 0
q:
qReqConf
qReqStat
role:
dev 1
tmpl:
Attributes:
IODev VCCU
IOgrp VCCU:HMLanGW
alias DisplayGarage
autoReadReg 4_reqStatus
expert 2_raw
firmware 1.2
model HM-Dis-EP-WM55
msgRepeat 5
room CUL_HM
serialNr NEQ0711879
subType display
webCmd getConfig:clear msgEvents
Das Gerät funktioniert grundsätzlich, nur eben alle 2-3 Tage reisst es den FHEM nieder.
LG
Mike
ich vermute folgendes attribut macht probleme, denn da muss ein echtes io drin stehen. also mal ändern.
IODev VCCU
edit:
ausserdem gibt es bei dir ein problem mit der zentrale und/oder den io's.
gepairt ist mit 0xDEAD11 die fehlermeldung kommt aber von 0xF10000. diese "falsche" zentrale erzeugt auch die sabottage readings.
hast du das list manipuliert?
nutzt du eventuell noch einen cul, der nicht in der vccu ist?
zeig mal ein list der vccu.
Hi,
ich hab' das IODev mal geändert, mal sehen ob es das verbessert, danke für den Hinweis.
Nein, der Output ist nicht manipuliert, der ist 1:1 reinkopiert.
Ich nutze keinen CUL, ich nutze ein eQ3-HM-LGW und einen HM-CFG-LAN.
Hier das list der VCCU:
Internals:
DEF DEAD11
HMLANWZ_MSGCNT 825
HMLANWZ_RAWMSG EDEAD11,0000,000DA09A,FF,FFB8,3D8002DEAD114C201A00
HMLANWZ_RSSI -72
HMLANWZ_TIME 2018-12-08 15:44:28
HMLanGW_MSGCNT 216
HMLanGW_RAWMSG 05000044688002DEAD114F24C001012300
HMLanGW_RSSI -68
HMLanGW_TIME 2018-12-08 15:46:35
IODev HMLanGW
LASTInputDev HMLanGW
MSGCNT 1041
NAME VCCU
NOTIFYDEV global
NR 16
NTFY_ORDER 50-VCCU
STATE HMLanGW:ok,HMLANWZ:ok,
TYPE CUL_HM
assignedIOs HMLANWZ,HMLanGW
channel_01 VCCU_Btn1
lastMsg No:68 - t:02 s:DEAD11 d:4F24C0 01012300
protLastRcv 2018-12-08 15:46:35
protRcv 603 last_at:2018-12-08 15:46:35
protRcvB 69 last_at:2018-12-08 15:36:47
rssi_at_HMLANWZ cnt:801 min:-75 max:-58 avg:-64.73 lst:-72
rssi_at_HMLanGW cnt:216 min:-79 max:-56 avg:-62.25 lst:-68
READINGS:
2018-12-08 15:46:34 CommandAccepted yes
2018-12-08 15:43:09 aesKeyNbr 00
2018-10-27 11:00:08 aesReqTo HM_4BD524
2018-12-08 15:43:53 state HMLanGW:ok,HMLANWZ:ok,
2016-10-28 13:12:20 unknown_36D02F received
2017-10-21 10:05:31 unknown_4553A5 received
2016-10-28 12:37:40 unknown_4553A6 received
2016-10-28 12:50:17 unknown_4553B4 received
2018-09-23 11:10:23 unknown_4BD517 received
2016-10-31 11:21:08 unknown_4C201A received
2016-10-31 11:30:40 unknown_4C2079 received
2017-01-01 11:32:04 unknown_4C48C5 received
2017-08-23 08:06:37 unknown_4D118D received
2017-08-18 06:28:58 unknown_4DEA30 received
2017-08-18 14:39:10 unknown_4DEB5D received
2017-08-18 14:10:56 unknown_4DEB66 received
2017-08-18 06:52:25 unknown_4DEB7B received
2017-06-09 17:19:07 unknown_4E9AA9 received
2017-09-26 19:37:41 unknown_4F24C0 received
2017-09-26 19:44:38 unknown_4F24CA received
2017-11-01 09:25:45 unknown_4F9D7E received
2018-12-08 15:01:53 unknown_504C9B received
2018-01-04 13:17:37 unknown_5152D7 received
2017-06-03 09:08:25 unknown_5196AB received
2017-10-14 12:14:43 unknown_54BB05 received
2017-10-14 12:14:32 unknown_54BCAF received
2018-02-16 10:50:21 unknown_562E6B received
2017-08-27 10:49:06 unknown_587FEE received
2017-08-27 10:28:43 unknown_58801D received
2017-11-01 09:42:24 unknown_5AE7AF received
2018-09-14 17:40:17 unknown_5AEEAD received
2018-12-08 15:41:14 unknown_788A4E received
2017-03-05 11:57:05 unknown_7AA942 received
2017-10-08 17:12:01 unknown_999999 received
2018-11-19 05:58:03 unknown_9D6BB1 received
2018-12-06 00:53:27 unknown_B879F9 received
2018-08-26 19:34:26 unknown_BC24D5 received
2018-12-08 12:59:04 unknown_F10000 received
helper:
HM_CMDNR 104
PONtest 1
mId FFF0
regLst ,0
rxType 1
supp_Pair_Rep 0
ack:
expert:
def 1
det 0
raw 1
tpl 0
io:
nextSend 1544280395.33602
prefIO
vccu VCCU
ioList:
HMLanGW
HMLANWZ
mRssi:
mNo 68
io:
HMLANWZ:
-72
HMLanGW:
-64
-64
prt:
bErr 0
sProc 0
rspWait:
q:
qReqConf
qReqStat
role:
dev 1
vrt 1
rssi:
at_HMLANWZ:
avg -64.7328339575532
cnt 801
lst -72
max -58
min -75
at_HMLanGW:
avg -62.2546296296296
cnt 216
lst -68
max -56
min -79
shadowReg:
Attributes:
IODev HMLanGW
IOList HMLanGW,HMLANWZ
IOgrp VCCU
expert 2_raw
group Interfaces
icon it_wifi
model CCU-FHEM
room System
subType virtual
webCmd virtual:update
Hi,
Zitat von: XXL-Wing am 08 Dezember 2018, 12:55:54
2018.12.08 12:48:23 1: HMUARTLGW HMLanGW: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B001F100004BD52401050000000001
Auch eine Configuration-Message, interessant.
Zitat
Hier das gewünschte List des Devices:
Hmm, bis auf das schon angemerkte IODev leider nichts aussergewöhnliches.
Ich hätte eine große Bitte:
Kannst Du bitte in 00_HMUARTLGW.pm nach der Meldung ein stacktrace(); einfügen? Also so (Zeile 1577):
Index: FHEM/00_HMUARTLGW.pm
===================================================================
--- FHEM/00_HMUARTLGW.pm (revision 17923)
+++ FHEM/00_HMUARTLGW.pm (working copy)
@@ -1574,6 +1574,7 @@
!defined($hash->{Helper}{FW})) {
Log3($hash, 1, "HMUARTLGW ${name}: Device not initialized (state: $hash->{DevState}, " .
ReadingsVal($name, "cond", "").") but asked to send data. Dropping: ${msg}");
+ stacktrace();
return;
}
Dann kriegst Du zwar zusätzlich viele Stacktraces ins Logfile, aber hoffentlich bringen die Erleuchtung.
Danke & Viele Grüße
Michael
Hi,
ist eingebaut.
Nach Murphy's Law wird jetzt nix mehr passieren ;-)
Ich melde mich wenn es da was "sehbares" gibt.
Vielen Dank schon mal für die Unterstützung!
lG
Mike
Kein Murphy, kam ja recht fix, hier die relevanten Log-Teile:
2018.12.09 15:45:53 1: HMUARTLGW HMLanGW: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As0A778002DEAD1137B07600
2018.12.09 15:45:53 1: stacktrace:
2018.12.09 15:45:53 1: main::HMUARTLGW_Write called by fhem.pl (1000)
2018.12.09 15:45:53 1: main::IOWrite called by ./FHEM/10_CUL_HM.pm (7025)
2018.12.09 15:45:53 1: main::CUL_HM_SndCmd called by ./FHEM/10_CUL_HM.pm (2967)
2018.12.09 15:45:53 1: main::CUL_HM_Parse called by fhem.pl (3799)
2018.12.09 15:45:53 1: main::Dispatch called by ./FHEM/00_HMLAN.pm (779)
2018.12.09 15:45:53 1: main::HMLAN_Parse called by ./FHEM/00_HMLAN.pm (604)
2018.12.09 15:45:53 1: main::HMLAN_Read called by fhem.pl (3603)
2018.12.09 15:45:53 1: main::CallFn called by fhem.pl (726)
2018.12.09 15:45:53 1: HMUARTLGW HMLanGW: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As0A788002DEAD1137B07600
2018.12.09 15:45:53 1: stacktrace:
2018.12.09 15:45:53 1: main::HMUARTLGW_Write called by fhem.pl (1000)
2018.12.09 15:45:53 1: main::IOWrite called by ./FHEM/10_CUL_HM.pm (7025)
2018.12.09 15:45:53 1: main::CUL_HM_SndCmd called by ./FHEM/10_CUL_HM.pm (2967)
2018.12.09 15:45:53 1: main::CUL_HM_Parse called by fhem.pl (3799)
2018.12.09 15:45:53 1: main::Dispatch called by ./FHEM/00_HMLAN.pm (779)
2018.12.09 15:45:53 1: main::HMLAN_Parse called by ./FHEM/00_HMLAN.pm (604)
2018.12.09 15:45:53 1: main::HMLAN_Read called by fhem.pl (3603)
2018.12.09 15:45:53 1: main::CallFn called by fhem.pl (726)
2018.12.09 15:45:53 1: HMUARTLGW HMLanGW: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As0A798002DEAD1137B07600
2018.12.09 15:45:53 1: stacktrace:
2018.12.09 15:45:53 1: main::HMUARTLGW_Write called by fhem.pl (1000)
2018.12.09 15:45:53 1: main::IOWrite called by ./FHEM/10_CUL_HM.pm (7025)
2018.12.09 15:45:53 1: main::CUL_HM_SndCmd called by ./FHEM/10_CUL_HM.pm (2967)
2018.12.09 15:45:53 1: main::CUL_HM_Parse called by fhem.pl (3799)
2018.12.09 15:45:53 1: main::Dispatch called by ./FHEM/00_HMLAN.pm (779)
2018.12.09 15:45:53 1: main::HMLAN_Parse called by ./FHEM/00_HMLAN.pm (604)
2018.12.09 15:45:53 1: main::HMLAN_Read called by fhem.pl (3603)
2018.12.09 15:45:53 1: main::CallFn called by fhem.pl (726)
2018.12.09 15:45:53 1: HMUARTLGW HMLanGW: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As0A7A8002DEAD1137B07600
2018.12.09 15:45:53 1: stacktrace:
2018.12.09 15:45:53 1: main::HMUARTLGW_Write called by fhem.pl (1000)
2018.12.09 15:45:53 1: main::IOWrite called by ./FHEM/10_CUL_HM.pm (7025)
2018.12.09 15:45:53 1: main::CUL_HM_SndCmd called by ./FHEM/10_CUL_HM.pm (2967)
2018.12.09 15:45:53 1: main::CUL_HM_Parse called by fhem.pl (3799)
2018.12.09 15:45:53 1: main::Dispatch called by ./FHEM/00_HMLAN.pm (779)
2018.12.09 15:45:53 1: main::HMLAN_Parse called by ./FHEM/00_HMLAN.pm (604)
2018.12.09 15:45:53 1: main::HMLAN_Read called by fhem.pl (3603)
2018.12.09 15:45:53 1: main::CallFn called by fhem.pl (726)
2018.12.09 15:45:53 1: HMUARTLGW HMLanGW: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As0A7B8002DEAD1137B07600
2018.12.09 15:45:53 1: stacktrace:
2018.12.09 15:45:53 1: main::HMUARTLGW_Write called by fhem.pl (1000)
2018.12.09 15:45:53 1: main::IOWrite called by ./FHEM/10_CUL_HM.pm (7025)
2018.12.09 15:45:53 1: main::CUL_HM_SndCmd called by ./FHEM/10_CUL_HM.pm (2967)
2018.12.09 15:45:53 1: main::CUL_HM_Parse called by fhem.pl (3799)
2018.12.09 15:45:53 1: main::Dispatch called by ./FHEM/00_HMLAN.pm (779)
2018.12.09 15:45:53 1: main::HMLAN_Parse called by ./FHEM/00_HMLAN.pm (604)
2018.12.09 15:45:53 1: main::HMLAN_Read called by fhem.pl (3603)
2018.12.09 15:45:53 1: main::CallFn called by fhem.pl (726)
2018.12.09 15:45:53 1: HMUARTLGW HMLanGW: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As0A7C8002DEAD1137B07600
2018.12.09 15:45:53 1: stacktrace:
2018.12.09 15:45:53 1: main::HMUARTLGW_Write called by fhem.pl (1000)
2018.12.09 15:45:53 1: main::IOWrite called by ./FHEM/10_CUL_HM.pm (7025)
2018.12.09 15:45:53 1: main::CUL_HM_SndCmd called by ./FHEM/10_CUL_HM.pm (2967)
2018.12.09 15:45:53 1: main::CUL_HM_Parse called by fhem.pl (3799)
2018.12.09 15:45:53 1: main::Dispatch called by ./FHEM/00_HMLAN.pm (779)
2018.12.09 15:45:53 1: main::HMLAN_Parse called by ./FHEM/00_HMLAN.pm (604)
2018.12.09 15:45:53 1: main::HMLAN_Read called by fhem.pl (3603)
2018.12.09 15:45:53 1: main::CallFn called by fhem.pl (726)
2018.12.09 15:45:53 1: HMLAN_Parse: HMLANWZ new condition ok
Hi,
Zitat von: XXL-Wing am 09 Dezember 2018, 16:09:42
2018.12.09 15:45:53 1: HMUARTLGW HMLanGW: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As0A778002DEAD1137B07600
2018.12.09 15:45:53 1: stacktrace:
2018.12.09 15:45:53 1: main::HMUARTLGW_Write called by fhem.pl (1000)
2018.12.09 15:45:53 1: main::IOWrite called by ./FHEM/10_CUL_HM.pm (7025)
2018.12.09 15:45:53 1: main::CUL_HM_SndCmd called by ./FHEM/10_CUL_HM.pm (2967)
2018.12.09 15:45:53 1: main::CUL_HM_Parse called by fhem.pl (3799)
2018.12.09 15:45:53 1: main::Dispatch called by ./FHEM/00_HMLAN.pm (779)
2018.12.09 15:45:53 1: main::HMLAN_Parse called by ./FHEM/00_HMLAN.pm (604)
2018.12.09 15:45:53 1: main::HMLAN_Read called by fhem.pl (3603)
2018.12.09 15:45:53 1: main::CallFn called by fhem.pl (726)
Interessant, hier wird das Problem durch ein Paket ausgelöstet, welches von dem HM-CFG-LAN empfangen wurde. Also scheint es unabhängig vom empfangenden IO zu sein (der Threadersteller hat wohl nur HMUARTs und ich habe das auch einmal auf meinem HMUART Dev-System gesehen).
Die while-Schleife in Zeile 2967 in 10_CUL_HM.pm ist die einzige Stelle, die mir jetzt als evtl. Auslöser auffällt, auch wenn ich mir gerade nicht erklären kann, wie die nicht abbricht und immer wieder die gleiche Nachricht sendet.
Schuss ins Blaue:
Index: FHEM/10_CUL_HM.pm
===================================================================
--- FHEM/10_CUL_HM.pm (revision 17923)
+++ FHEM/10_CUL_HM.pm (working copy)
@@ -2965,7 +2965,7 @@
.($mh{devH}->{helper}{aesAuthBytes}
?$mh{devH}->{helper}{aesAuthBytes}
:"")
- )while ($i<@ack);
+ )while ($i<int(@ack));
$respRemoved = $rr;
Log3 $mh{devN},5,"CUL_HM $mh{devN} sent ACK:".(int(@ack));
delete($mh{devH}->{helper}{aesAuthBytes});
@Martin: Hast Du irgendeine Idee, warum hier anscheinend CUL_HM in einer Endlosschleife versucht eine Nachricht abzusenden (es kann natürlich auch immernoch ein Fehler in HMUARTLGW sein, auch wenn ich da in dem entsprechenden Codepfad keine Schleife sehe, die das auslösen könnte)?
Viele Grüße
Michael
Hi,
Habe den Code mal übernommen.
In der ersten halben Stunde nichts mehr im Log. Ich melde mich wieder wenn es Neuigkeiten gibt.
LG
Mike
Hallo Michael,
wäre es nicht auch noch interessant, zusätzlich zum Stacktrace auch noch verbose auf 5 für das IO hoch zu setzen?
CUL_HM_SndCmd schreibt nur ans IO. In Endlosschleife wundert mich dann erst mal die komplette Wiederholung des Ablaufs mit Read.
Wäre auch möglich, dass etwas beim Lesen im Empfangspuffer hängen bleibt und immer wieder "empfangen" wird.
Mit verbose = 5 würde das sichtbar werden.
Gruß, Ansgar.
Hallo Ansgar,
Zitat von: noansi am 09 Dezember 2018, 18:58:37
wäre es nicht auch noch interessant, zusätzlich zum Stacktrace auch noch verbose auf 5 für das IO hoch zu setzen?
Ja.
Zitat
In Endlosschleife wundert mich dann erst mal die komplette Wiederholung des Ablaufs mit Read.
Aeh, wieso? Wenn es mitten im Stacktrace eine Endlosschleife gibt, dann sieht alles vor der Schleife immer gleich aus.
Zitat
Wäre auch möglich, dass etwas beim Lesen im Empfangspuffer hängen bleibt und immer wieder "empfangen" wird.
Ja, aber das müsste dann ein Bug sowohl in HMUARTLGW als auch in HMLAN sein, und bei beiden sieht der entsprechende Code korrekt aus. Beide Module benutzen DevIO.pm, aber auch das sieht auf dem entsprechenden Pfad sauber aus.
Zitat
Mit verbose = 5 würde das sichtbar werden.
Ja, mehr debug-Messages wären auf jeden Fall nicht schlecht.
Viele Grüße
Michael
Hallo Michael,
ZitatAeh, wieso? Wenn es mitten im Stacktrace eine Endlosschleife gibt, dann sieht alles vor der Schleife immer gleich aus.
Oh, danke für den Hinweis. Ich habe stacktrace noch nie genutzt.
ZitatJa, aber das müsste dann ein Bug sowohl in HMUARTLGW als auch in HMLAN sein, und bei beiden sieht der entsprechende Code korrekt aus. Beide Module benutzen DevIO.pm, aber auch das sieht auf dem entsprechenden Pfad sauber aus.
Mir ist da auch kein Fehler aufgefallen.
stacktrace(); $attr{$name}{"verbose"}=5;Wäre mein Änderungsvorschlag, um das Log vor dem ersten stacktrace nicht voll zu müllen, aber mehr Output zu generieren.
Dein Änderungsvorschlag zur u.U. tückischen Abfrage von @ack kann durchaus schon die Lösung sein.
Gruß, Ansgar.
Servus,
danke für die vielen Rückmeldungen :-)
Ich habe die Erhöhung des verbose Levels nach dem stacktrace Aufruf eingefügt.
Seit der vorgeschlagenen Änderung mit dem @ack ist kein stacktrace mehr aufgetreten.
Soweit zur guten Nachricht.
Die schlechte ist dass seither das LAN CFG Modul öfter in kurzen Abständen offline geht, sich dann wieder für ein paar Stunden fängt. Kann Zufall sein aber die Häufigkeit entspricht etwa der Anzahl der stacktraces....
2018.12.10 16:48:57 1: HMLAN_Parse: HMLANWZ new condition disconnected
2018.12.10 16:48:57 1: 192.168.0.12:1000 disconnected, waiting to reappear (HMLANWZ)
2018.12.10 16:48:57 1: HMLAN_Parse: HMLANWZ new condition disconnected
2018.12.10 16:48:58 1: HMLAN_Parse: HMLANWZ new condition init
2018.12.10 16:48:58 1: 192.168.0.12:1000 reappeared (HMLANWZ)
2018.12.10 16:48:58 1: HMLAN_Parse: HMLANWZ new condition ok
2018.12.10 16:49:48 1: 192.168.0.12:1000 disconnected, waiting to reappear (HMLANWZ)
2018.12.10 16:49:48 1: HMLAN_Parse: HMLANWZ new condition disconnected
2018.12.10 16:49:48 1: HMLAN_Parse: HMLANWZ new condition init
2018.12.10 16:49:48 1: 192.168.0.12:1000 reappeared (HMLANWZ)
2018.12.10 16:49:48 1: HMLAN_Parse: HMLANWZ new condition ok
2018.12.10 16:50:13 1: 192.168.0.12:1000 disconnected, waiting to reappear (HMLANWZ)
2018.12.10 16:50:13 1: HMLAN_Parse: HMLANWZ new condition disconnected
2018.12.10 16:50:13 1: HMLAN_Parse: HMLANWZ new condition init
2018.12.10 16:50:13 1: 192.168.0.12:1000 reappeared (HMLANWZ)
2018.12.10 16:50:13 1: HMLAN_Parse: HMLANWZ new condition ok
2018.12.10 16:52:17 3: UWZ Unwetterzentrale: Run.1219 Done fetching data
2018.12.10 16:58:08 1: 192.168.0.12:1000 disconnected, waiting to reappear (HMLANWZ)
2018.12.10 16:58:08 1: HMLAN_Parse: HMLANWZ new condition disconnected
2018.12.10 16:58:08 1: HMLAN_Parse: HMLANWZ new condition init
2018.12.10 16:58:08 1: 192.168.0.12:1000 reappeared (HMLANWZ)
2018.12.10 16:58:08 1: HMLAN_Parse: HMLANWZ new condition ok
lG
Mike
hat der hmlan fw0.965?
Hier ist ja einiges passiert wieder :)
Ich konnte mein Problem zwar nicht nicht lösen aber zumindest tritt es nicht mehr alle halbe Stunde bis Stunde auf sondern nur noch einzeln verteilt über den Tag. Hat es vielleicht doch was damit zu tun, dass sich die Thermostate immer mehr Konfigurationen gezogen haben? Ich werde aber mal die entsprechenden Zeilen Code ändern und dann mal weiter Info hier preisgeben, vielleicht wurde die Lösung ja schon gepostet.
Zitat von: mgernoth am 04 Dezember 2018, 20:16:21
Hallo,
Was ist 5C1747? Diese Konfigurationsmessage für dieses Geräts löst das Problem aus.
Was hier passiert ist, dass CUL_HM in einer Endlosschleife diese Message sendet. Die Meldungen von HMUARTLGW sind nur Symptom, nicht Ursache. Ich hatte das auch einmal bisher, konnte es aber nicht reproduzieren und damit auch nicht debuggen...
Kannst Du bitte mal ein List von 5C1747 posten?
Viele Grüße
Michael
sorry ganz übersehen. hier das list:
Internals:
DEF 5C1747
IODev 3051_PEQ0174459
NAME HM_5C1747
NOTIFYDEV global
NR 2549
NTFY_ORDER 50-HM_5C1747
STATE CMDs_pending
TYPE CUL_HM
channel_01 HM_5C1747_Weather
channel_02 HM_5C1747_Climate
channel_03 HM_5C1747_WindowRec
channel_06 HM_5C1747_remote
channel_07 HM_5C1747_SwitchTr
READINGS:
2018-12-11 10:57:53 Activity unknown
2018-12-03 18:13:13 CommandAccepted yes
2018-11-15 17:28:53 D-firmware 1.3
2018-11-15 17:28:53 D-serialNr OEQ0849210
2018-11-23 13:22:14 PairedTo 0x45FF96
2018-11-23 13:22:14 R-burstRx on
2018-11-23 13:22:14 R-cyclicInfoMsg on
2018-11-23 13:22:14 R-cyclicInfoMsgDis 0
2018-11-23 13:22:14 R-pairCentral 0x45FF96
2018-11-23 13:22:14 RegL_00. 01:01 02:01 09:01 0A:45 0B:FF 0C:96 0F:00 11:00 12:16 16:00 18:00 19:00 1A:00
2018-11-23 14:18:45 RegL_07.
2018-12-11 01:30:40 battery ok
2018-12-11 01:30:40 batteryLevel 2.9
2018-12-11 01:30:40 desired-temp 21.0
2018-12-11 01:30:40 measured-temp 20.4
2018-12-03 18:28:34 state CMDs_pending
helper:
HM_CMDNR 221
mId 00AD
regLst ,0
rxType 6
expert:
def 1
det 0
raw 1
tpl 0
io:
newChn +5C1747,00,00,00
prefIO
rxt 0
vccu VCCU0
p:
5C1747
00
00
00
mRssi:
mNo
prt:
bErr 0
sProc 0
q:
qReqConf 00
qReqStat
role:
dev 1
prs 1
shRegW:
07 02
tmpl:
Attributes:
IODev 3051_PEQ0174459
IOgrp VCCU0
actCycle 000:10
actStatus unknown
autoReadReg 5_readMissing
expert 2_raw
firmware 1.3
model HM-TC-IT-WM-W-EU
msgRepeat 1
room CUL_HM
serialNr OEQ0849210
subType thermostat
webCmd getConfig:clear msgEvents
Vor einer Stunde ist es wieder passiert. Hier mal mit der Änderung am Code:
2018.12.12 08:45:01 5: HMUARTLGW 4160_PEQ0533574 HMUARTLGW_Write: As1001B00145FF965B676F00050000000000
2018.12.12 08:45:01 1: HMUARTLGW 4160_PEQ0533574: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B00145FF965B676F00050000000000
2018.12.12 08:45:01 1: stacktrace:
2018.12.12 08:45:01 1: main::HMUARTLGW_Write called by fhem.pl (1000)
2018.12.12 08:45:01 1: main::IOWrite called by ./FHEM/10_CUL_HM.pm (7191)
2018.12.12 08:45:01 1: main::CUL_HM_respPendTout called by fhem.pl (3146)
2018.12.12 08:45:01 1: main::HandleTimeout called by fhem.pl (649)
Hi,
Zitat von: gritob am 12 Dezember 2018, 09:48:06
Vor einer Stunde ist es wieder passiert. Hier mal mit der Änderung am Code:
2018.12.12 08:45:01 5: HMUARTLGW 4160_PEQ0533574 HMUARTLGW_Write: As1001B00145FF965B676F00050000000000
2018.12.12 08:45:01 1: HMUARTLGW 4160_PEQ0533574: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B00145FF965B676F00050000000000
2018.12.12 08:45:01 1: stacktrace:
2018.12.12 08:45:01 1: main::HMUARTLGW_Write called by fhem.pl (1000)
2018.12.12 08:45:01 1: main::IOWrite called by ./FHEM/10_CUL_HM.pm (7191)
2018.12.12 08:45:01 1: main::CUL_HM_respPendTout called by fhem.pl (3146)
2018.12.12 08:45:01 1: main::HandleTimeout called by fhem.pl (649)
Vielen Dank, dieser Backtrace sieht eher so aus, wie ich er erwartet hätte. Irgendwo wird ein Resend ständig wiederholt und führt zu dem Problem. "Eigentlich" dürfte das gar nicht passieren können...
Auf Anhieb sehe ich nichts falsches an dem Code, da gibts aber eine Menge Pfade, die zu diesem Zustand führen können...
Woher kommt die Uhrzeit des Systems? Gibt es hier evtl. sync-Vorgänge direkt vor dem Auftreten des Problems, welche das evtl. verursachen könnten?
EDIT: Wenn ich jetzt mal den vorherigen Backtrace ausser acht lasse (evtl. weil er indirekt ausgeloest wurde), dann sind die drei anderen in diesem Thread gemeldeten Pakete Configuration-Pakete an Burst-Devices und auch noch die erste Nachricht an das jeweilige Gerät(As xx 01 B0). Das sieht mir schon sehr nach einer Gemeinsamkeit aus und nicht nach Zufall:
As1001B00145FF965C174700050000000000
As1001B001F100004BD52401050000000001
As1001B00145FF965B676F00050000000000
@gritob: 5B676F ist auch ein WT? Kannst Du mal bei allen WT autoReadReg auf 4 runtersetzen?
Viele Grüße
Michael
5B676F ist auch ein WT korrekt! Habe mal autoReadReg für alle WT auf 4 geändert. Uhrzeit ist ne gute Frage. Bei mir läuft FHEM in einem Ubuntu 16.04.2 LTS in einer ESXI VM. Sind mit Sicherheit die Standard Zeitserver angeben, wie oft da ein sync passiert kann ich da aber nicht sagen.
Hier nochmal von heute morgen:
2018.12.13 07:55:01 5: HMUARTLGW 4151_PEQ0533636 HMUARTLGW_Write: As1001B00145FF965B124B00050000000000
2018.12.13 07:55:01 1: HMUARTLGW 4151_PEQ0533636: Device not initialized (state: 2, init) but asked to send data. Dropping: As1001B00145FF965B124B00050000000000
2018.12.13 07:55:01 1: stacktrace:
2018.12.13 07:55:01 1: main::HMUARTLGW_Write called by fhem.pl (1000)
2018.12.13 07:55:01 1: main::IOWrite called by ./FHEM/10_CUL_HM.pm (7191)
2018.12.13 07:55:01 1: main::CUL_HM_respPendTout called by fhem.pl (3146)
2018.12.13 07:55:01 1: main::HandleTimeout called by fhem.pl (649)
vielleicht auch noch interessant für euch:
2018.12.13 07:41:43 1: HMUARTLGW 4151_PEQ0533636: queue is full, dropping packet
2018.12.13 07:41:43 1: HMUARTLGW 4151_PEQ0533636: queue is full, dropping packet
das wird halt vorher gespammt, hatte ich aber schon erwähnt meine ich.
Hi,
Zitat von: gritob am 13 Dezember 2018, 17:13:42
Uhrzeit ist ne gute Frage. Bei mir läuft FHEM in einem Ubuntu 16.04.2 LTS in einer ESXI VM.
Hmm, VM könnte evtl. ein Problem sein, das ist aber sehr unwahrscheinlich. Manchmal synchronisieren die Hypervisor hart von aussen.
Zitat
Hier nochmal von heute morgen:
Hoffentlich bevor Du autoReadReg geändert hast?
Zitat
2018.12.13 07:55:01 5: HMUARTLGW 4151_PEQ0533636 HMUARTLGW_Write: As1001B00145FF965B124B00050000000000
Ah, Du hast den Vorschlag von noansi umgesetzt :-)
Ist das die einzige HMUARTLGW-Zeile zwischen den Backtraces?
Wenn ja dann ist es eindeutig nicht der Receive-Pfad der da noch dazwischenfunkt.
Zitat
vielleicht auch noch interessant für euch:
2018.12.13 07:41:43 1: HMUARTLGW 4151_PEQ0533636: queue is full, dropping packet
2018.12.13 07:41:43 1: HMUARTLGW 4151_PEQ0533636: queue is full, dropping packet
das wird halt vorher gespammt, hatte ich aber schon erwähnt meine ich.
Ja, das ist die Vorstufe des gleichen Problems bis dann irgendwann das Modul aufgibt und die "not initialized" Meldung kommt.
Viele Grüße
Michael
ZitatHmm, VM könnte evtl. ein Problem sein, das ist aber sehr unwahrscheinlich. Manchmal synchronisieren die Hypervisor hart von aussen.
Die VM Konfiguration habe ich so 100+ Mal laufen wenn ich es abschätzen müsste. Unterschied ist hier jetzt nur, dass es hier sehr viele Wandthermostate gibt. Teilweise habe ich noch größere Systeme am laufen, die jedoch nur aus normalen Thermostaten bestehen und die laufen ohne Fehler. Ich konnte den Fehler jetzt auch nochmal bei einem kleineren System beobachten, da gibt es jedoch auch sehr viele Wandthermostate. Ich vermute wirklich, dass es irgendwie damit zusammenhängen muss. Vielleicht hilft das. Ich teste gerne alles und kann den Fehler denke ich sehr schnell reproduzieren, spätestens dann, wenn ich viele getConfigs mache, kann ich es bestimmt sogar erzwingen. Momentan hab ich so eine Bauernlösung am Laufen, dass mir FHEM in einem cronjob killt, wenn es in den Modus fährt und dann wieder hochfährt. Funktioniert zwar aber kann auch keine Dauerlösung sein :'(
ZitatIst das die einzige HMUARTLGW-Zeile zwischen den Backtraces?
Leider ja, das was ich gepostet habe steht dann so quasi gefühlt mehrere 100 Male in der Datei. Ist immer ein anderer HMUART.
Hier nochmal nach der autoReadReg Änderung. Hab hier sogar eine Stelle gefunden wo es 2 betrifft:
2018.12.14 07:35:01 5: HMUARTLGW 4151_PEQ0533636 HMUARTLGW_Write: As1001B00145FF965B124B00050000000000
2018.12.14 07:35:01 1: HMUARTLGW 4151_PEQ0533636: Device not initialized (state: 0, disconnected) but asked to send data. Dropping: As1001B00145FF965B124B00050000000000
2018.12.14 07:35:01 1: stacktrace:
2018.12.14 07:35:01 1: main::HMUARTLGW_Write called by fhem.pl (1000)
2018.12.14 07:35:01 1: main::IOWrite called by ./FHEM/10_CUL_HM.pm (7191)
2018.12.14 07:35:01 1: main::CUL_HM_respPendTout called by fhem.pl (3146)
2018.12.14 07:35:01 1: main::HandleTimeout called by fhem.pl (649)
2018.12.14 07:35:01 5: HMUARTLGW 4160_PEQ0533574 HMUARTLGW_Write: As1001B00145FF965C171400050000000000
2018.12.14 07:35:01 1: HMUARTLGW 4160_PEQ0533574: Device not initialized (state: 3, init) but asked to send data. Dropping: As1001B00145FF965C171400050000000000
2018.12.14 07:35:01 1: stacktrace:
2018.12.14 07:35:01 1: main::HMUARTLGW_Write called by fhem.pl (1000)
2018.12.14 07:35:01 1: main::IOWrite called by ./FHEM/10_CUL_HM.pm (7191)
2018.12.14 07:35:01 1: main::CUL_HM_respPendTout called by fhem.pl (3146)
2018.12.14 07:35:01 1: main::HandleTimeout called by fhem.pl (649)
Hallo Michael,
disconnected in den Logs für HMUARTLGW gibt den Zustand von "cond" wieder, nicht aber den von "state", wie es in CUL_HM_respPendTout Zeile 7131 mit
elsif (ReadingsVal($hash->{IODev}->{NAME},"state","") !~ m/^(opened|Initialized)$/){#IO errors
CUL_HM_eventP($hash,"IOdly");
CUL_HM_ProcessCmdStack($hash) if($rxt & 0x03);#burst/all
}
abgefragt wird.
Kann es in dem Zustand bei HMUARTLGW sein, dass "state" auf opened oder Initialized steht, obwohl "cond" disconnected besagt?
Und sollte die Abfrage im CUL_HM code oben nicht eher in
elsif ( (defined $hash->{IODev}->{XmitOpen} && $hash->{IODev}->{XmitOpen} < 1)
|| ReadingsVal($hash->{IODev}->{NAME},"state","") !~ m/^(opened|Initialized)$/ ){#IO errors
geändert werden?
Oder noch besser mit Überlastbehandlung.
Gruß, Ansgar.
Hallo Michael, hallo Martin,
der Pfad ab Zeile 7174 wird in den letzten Stacktraces in CUL_HM ausgeführt:
else{# normal device resend
if ($rxt & 0x02){# type = burst - need to set burst-Bit for retry
if ($pHash->{mmcA}){#fillback multi-message command
unshift @{$hash->{cmdStack}},$_ foreach (reverse@{$pHash->{mmcA}});
delete $pHash->{mmcA};
delete $pHash->{mmcS};
my $cmd = shift @{$hash->{cmdStack}};
$cmd = sprintf("As%02X01%s", length($cmd)/2, substr($cmd,2));
$pHash->{rspWait}{cmd} = $cmd;
CUL_HM_responseSetup($hash,$cmd);
}
my ($pre,$tp,$tail) = unpack 'A6A2A*',$pHash->{rspWait}{cmd};
$pHash->{rspWait}{cmd} = sprintf("%s%02X%s",$pre,(hex($tp)|0x10),$tail);
}
IOWrite($hash, "", $pHash->{rspWait}{cmd});
CUL_HM_eventP($hash,"SndB") if(hex(substr($pHash->{rspWait}{cmd},6,2)) & 0x10);
CUL_HM_statCnt($hash->{IODev}{NAME},"s",hex(substr($pHash->{rspWait}{cmd},6,2)));
InternalTimer(gettimeofday()+rand(20)/10+4,"CUL_HM_respPendTout","respPend:$hash->{DEF}", 0);
}
CUL_HM_responseSetup setzt $pHash->{rspWait}{reSent} erneut zurück.
Daher vermute ich mal, es sollte der aktuelle {reSent} Wert in {wuReSent} geschrieben werden.
Also folgender Ergänzungsvorschlag, um ständiges Wiederholen zu unterbinden:
else{# normal device resend
if ($rxt & 0x02){# type = burst - need to set burst-Bit for retry
if ($pHash->{mmcA}){#fillback multi-message command
unshift @{$hash->{cmdStack}},$_ foreach (reverse@{$pHash->{mmcA}});
delete $pHash->{mmcA};
delete $pHash->{mmcS};
my $cmd = shift @{$hash->{cmdStack}};
$cmd = sprintf("As%02X01%s", length($cmd)/2, substr($cmd,2));
$pHash->{rspWait}{cmd} = $cmd;
$pHash->{wuReSent} = $pHash->{rspWait}{reSent};# save 'invalid' count
CUL_HM_responseSetup($hash,$cmd);
}
my ($pre,$tp,$tail) = unpack 'A6A2A*',$pHash->{rspWait}{cmd};
$pHash->{rspWait}{cmd} = sprintf("%s%02X%s",$pre,(hex($tp)|0x10),$tail);
}
IOWrite($hash, "", $pHash->{rspWait}{cmd});
CUL_HM_eventP($hash,"SndB") if(hex(substr($pHash->{rspWait}{cmd},6,2)) & 0x10);
CUL_HM_statCnt($hash->{IODev}{NAME},"s",hex(substr($pHash->{rspWait}{cmd},6,2)));
InternalTimer(gettimeofday()+rand(20)/10+4,"CUL_HM_respPendTout","respPend:$hash->{DEF}", 0);
}
Zur zur ständigen Wiederholung gehört aber auch, dass die Funkverbindung zum device schlecht sein müsste, oder es die Message nicht beantwortet?
Oder die message gar nicht gesendet wird und deswegen keine Antwort kommt.
Gruß, Ansgar.
Hallo,
Update von meiner Seite...
Die Logeinträge mit dauerhaften retries sind mit dem neuen ack im Code ausgeblieben, die permanenten disconnects des LAN Configdaapters sind aber geblieben...
Das zweite LAN-GW hat derartige Probleme nicht.
Netzwerkprobleme kann ich ausschließen, der Switch hat nix in den Management logs und auch andere Geräte am selben Switch haben stabile Verbindung...
Firmware Version des LAN-CFG ist
0.964
LG
Mike
dann mach mal ein update auf 0.965.
Zitat von: noansi am 14 Dezember 2018, 21:42:27
Hallo Michael, hallo Martin,
der Pfad ab Zeile 7174 wird in den letzten Stacktraces in CUL_HM ausgeführt:
else{# normal device resend
if ($rxt & 0x02){# type = burst - need to set burst-Bit for retry
if ($pHash->{mmcA}){#fillback multi-message command
unshift @{$hash->{cmdStack}},$_ foreach (reverse@{$pHash->{mmcA}});
delete $pHash->{mmcA};
delete $pHash->{mmcS};
my $cmd = shift @{$hash->{cmdStack}};
$cmd = sprintf("As%02X01%s", length($cmd)/2, substr($cmd,2));
$pHash->{rspWait}{cmd} = $cmd;
CUL_HM_responseSetup($hash,$cmd);
}
my ($pre,$tp,$tail) = unpack 'A6A2A*',$pHash->{rspWait}{cmd};
$pHash->{rspWait}{cmd} = sprintf("%s%02X%s",$pre,(hex($tp)|0x10),$tail);
}
IOWrite($hash, "", $pHash->{rspWait}{cmd});
CUL_HM_eventP($hash,"SndB") if(hex(substr($pHash->{rspWait}{cmd},6,2)) & 0x10);
CUL_HM_statCnt($hash->{IODev}{NAME},"s",hex(substr($pHash->{rspWait}{cmd},6,2)));
InternalTimer(gettimeofday()+rand(20)/10+4,"CUL_HM_respPendTout","respPend:$hash->{DEF}", 0);
}
CUL_HM_responseSetup setzt $pHash->{rspWait}{reSent} erneut zurück.
Daher vermute ich mal, es sollte der aktuelle {reSent} Wert in {wuReSent} geschrieben werden.
Also folgender Ergänzungsvorschlag, um ständiges Wiederholen zu unterbinden:
else{# normal device resend
if ($rxt & 0x02){# type = burst - need to set burst-Bit for retry
if ($pHash->{mmcA}){#fillback multi-message command
unshift @{$hash->{cmdStack}},$_ foreach (reverse@{$pHash->{mmcA}});
delete $pHash->{mmcA};
delete $pHash->{mmcS};
my $cmd = shift @{$hash->{cmdStack}};
$cmd = sprintf("As%02X01%s", length($cmd)/2, substr($cmd,2));
$pHash->{rspWait}{cmd} = $cmd;
$pHash->{wuReSent} = $pHash->{rspWait}{reSent};# save 'invalid' count
CUL_HM_responseSetup($hash,$cmd);
}
my ($pre,$tp,$tail) = unpack 'A6A2A*',$pHash->{rspWait}{cmd};
$pHash->{rspWait}{cmd} = sprintf("%s%02X%s",$pre,(hex($tp)|0x10),$tail);
}
IOWrite($hash, "", $pHash->{rspWait}{cmd});
CUL_HM_eventP($hash,"SndB") if(hex(substr($pHash->{rspWait}{cmd},6,2)) & 0x10);
CUL_HM_statCnt($hash->{IODev}{NAME},"s",hex(substr($pHash->{rspWait}{cmd},6,2)));
InternalTimer(gettimeofday()+rand(20)/10+4,"CUL_HM_respPendTout","respPend:$hash->{DEF}", 0);
}
Zur zur ständigen Wiederholung gehört aber auch, dass die Funkverbindung zum device schlecht sein müsste, oder es die Message nicht beantwortet?
Oder die message gar nicht gesendet wird und deswegen keine Antwort kommt.
Gruß, Ansgar.
vielleicht nochmal zur info. hab mal die zeile gestern hinzugefügt und bis jetzt ist es noch nicht wieder aufgetreten! ich werde weiterhin beobachten und mich melden.
nachtrag 19.12: bis jetzt immer noch nicht aufgetreten. ich gebe jetzt mal etwas last auf das system mit einigen befehlen um zu sehen, wie es sich dann verhält.
Nach 10 Tagen ist es immer noch wieder nicht aufgetreten :) Anscheinend habt ihr es gelöst für mich!
Hallo gritob,
und was passiert, wenn Du die Zeile nochmal raus nimmst?
Martin wird es wohl nur in die aktuelle Version einbauen, wenn es sich reproduzieren lässt.
Gruß, Ansgar.
Zitat von: noansi am 28 Dezember 2018, 16:31:09
Hallo gritob,
und was passiert, wenn Du die Zeile nochmal raus nimmst?
Martin wird es wohl nur in die aktuelle Version einbauen, wenn es sich reproduzieren lässt.
Gruß, Ansgar.
Dann kommt es wieder! Hab den Fehler jetzt auch bei nem anderen System gesehen wo es auch viele Wandthermostate gibt. Hab die Zeile dann 1-2 Mal ein- und auskommentiert. Es verschwindet und kommt dann wieder, je nachdem. Also hier funktioniert es wirklich einwandfrei. Weiss zwar nicht was ihr gemacht habt aber die Änderung aus dem letzten Post reicht aus für die Behebung.
das mit Ansgars Fix kann ich nicht nachvollziehen.
hier meine Fragen:
- Das problematische Device ist ein EP oder en TC?
- es ist immer das gleiche device?
- msgRepeat ist auf 1 gesetzt - damit wird max ein mal wiederholt (darf werden...)
- wenn der Fehler passiert werden nachrichten kontinuierlich wiederholt - alle 3 sec?
wenn der Fehler auftritt bitte
- verbose dieses Device auf 5 setzen
- beim HMLAN das Attribut logId setzen auf die HMid des problematischen Device.
- ein List des Device wenn der Fehler ansteht.
Hallo Martin,
ein Problemdevice ist ein TC. Das List war hier https://forum.fhem.de/index.php/topic,94035.msg870405.html#msg870405 (https://forum.fhem.de/index.php/topic,94035.msg870405.html#msg870405).
Problematische messages sind Burst messages gewesen, wie Michael schon bemerkt hatte, https://forum.fhem.de/index.php/topic,94035.msg871132.html#msg871132 (https://forum.fhem.de/index.php/topic,94035.msg871132.html#msg871132).
msgRepeat steht beim dem list auf 1, das hat mich auch gewundert, warum es bei dem mit der einen Zeile als Fix helfen sollte. Aber vielleicht war es ein temporärer Zustand. @gritob:
Daher bitte ein aktuelles "frisches" list.
Mehr Infos müssen die User mit Problemen versuchen zu liefern. Eventuell mal mit verbose 5 ab Systemstart für das HMLAN, damit die Vorgeschichte klarer wird.
Gruß, Ansgar.
Zitat von: martinp876 am 29 Dezember 2018, 16:25:24
das mit Ansgars Fix kann ich nicht nachvollziehen.
hier meine Fragen:
- Das problematische Device ist ein EP oder en TC?
- es ist immer das gleiche device?
- msgRepeat ist auf 1 gesetzt - damit wird max ein mal wiederholt (darf werden...)
- wenn der Fehler passiert werden nachrichten kontinuierlich wiederholt - alle 3 sec?
wenn der Fehler auftritt bitte
- verbose dieses Device auf 5 setzen
- beim HMLAN das Attribut logId setzen auf die HMid des problematischen Device.
- ein List des Device wenn der Fehler ansteht.
Frohes Neues, ich kann es bei Gelegenheit nochmal machen. Gibt da nur 1-2 Probleme.
- Ist ein TC
- es ist nicht immer das gleiche Device, weder das TC noch HMLAN
- msgRepeat ist immer noch auf 1 korrekt
- die Nachrichten werden nach Log viel häufiger wiederholt, geschätzt hunderte Male pro Sekunde und dann ist fhem auch tot.
- da es immer ein anderes Device ist, ist das mit dem verbose 5 schwierig
- ähnliches Problem hier auch, müsste theoretisch jeden HMLAN auf jedes in der Nähe erreichbare Device loggen lassen
- wenn der Fehler ansteht, dann kann ich leider Fhem gar nicht mehr bedienen. Also auch nicht per telnet.
Komm ich denn sonst noch etwas intelligenter an die Infos die für euch wichtig sind?
Du kannst auch einfach alle loggen lassen. Ich wollte nur die Größe reduzieren. Läuft bei mir aber kontinuierlich problemlos mit.
Hallo Martin,
Zitat von: martinp876 am 29 Dezember 2018, 16:25:24
das mit Ansgars Fix kann ich nicht nachvollziehen.
Bei einem Burst-Device kann folgendes passieren:
- CUL_HM_respPendTout inkrementiert $pHash->{rspWait}{reSent} (Zeile 7207)
- CUL_HM_respPendTout ruft CUL_HM_responseSetup auf (Zeile 7245)
- CUL_HM_responseSetup liest die resends nur aus $hash->{helper}{prt}{wuReSent} und wenn das leer ist wird 1 angenommen (Zeile 6830ff)
- CUL_HM_responseSetup ruft CUL_HM_respWaitSu mit diesen "falschen" Wert auf (an mehreren Stellen)
- CUL_HM_respWaitSu überschreibt das reSent im Device-Hash mit dem falschen Wert (Zeile 6811)
Damit gibt es dann ein endloses resend, da reSent nie die 3 erreicht.
Ansgars fix setzt vor dem Aufruf von
CUL_HM_responseSetup den Wert von
$hash->{helper}{prt}{wuReSent} auf den Wert aus
$hash->{rspWait}{reSent} und verhindert so das überschreiben. Evtl. ist der korrekte fix aber, in
CUL_HM_responseSetup die Variable
$rss nicht nur auf den Wert aus
$hash->{helper}{prt}{wuReSent} zu setzen sondern auch in
$hash->{rspWait}{reSent} zu schauen.
Viele Grüße
Michael
Hallo Michael, hallo Martin,
danke für's mitschauen!
Ich hatte mich zum Fix an Zeile 7230 und 7233 orientiert, das schien mir wegen der Nähe verständlicher und beeinflusst nicht die bisherige Funktion von CUL_HM_responseSetup/CUL_HM_respWaitSu, um nicht auf die schnelle den Teufel mit dem Beelzebub auszutreiben.
Auch wenn das Attribut msgRepeat auf 1 gesetzt ist, wird bei Zeile 7195 der Spuck nicht beendet, da erst in der Folge auf 2 erhöht wird, dann aber in CUL_HM_responseSetup/CUL_HM_respWaitSu für ein Burst device wieder zu 1 wird.
Zitat$hash->{rspWait}{reSent}
hatte ich als $hash->{helper}{prt}{rspWait}{reSent} verstanden?!
Gruß, Ansgar.
@Michael,
gute Analyse.
Das Problem ist 2. Ich nutze die Burst settings - aber das reSent wird gelöscht.
Ich rette es nun vorher.
@Ansgar: wuReSent macht auch so etwas - aber da es schon namentlich auch für Wakeup ist sollte man es nicht misbrauchen
comming today - danke euch beiden.