Hallo zusammen,
ich habe mehrere Homematic Thermostate im Einsatz, die ich über einen CUL -Stick anspreche und seit einiger Zeit kommt es zum Fhem-Absturz/Neustart wenn ich die Temperatur im Wohnzimmer über folgendes Decive s.u. verändere.
Die Temperatursteuerung über den Wochenplan funktioniert problemlos!
Internals:
DEF 6A202704
FUUID 5cd59b87-f33f-aed9-742c-5b3ccc8ec3df1d89
NAME HM_Hz_WZ_Clima
NR 969
NTFY_ORDER 48-HM_Hz_WZ_Clima
STATE T: 23.7 desired: 21.5 valve: 22
TYPE CUL_HM
chanNo 04
device HM_Hz_WZ
disableNotifyFn 1
Helper:
DBLOG:
ValvePosition:
logdb:
TIME 1649706318.31783
VALUE 22
desired-temp:
logdb:
TIME 1649706318.31783
VALUE 21.5
measured-temp:
logdb:
TIME 1649706318.31783
VALUE 23.9
READINGS:
2022-03-12 07:13:03 CommandAccepted yes
2021-01-18 10:12:46 R-boostPos 80 %
2021-01-18 10:12:46 R-btnNoBckLight off
2021-01-18 10:12:46 R-dayTemp 21 C
2021-01-18 10:12:46 R-daylightSaveTime on
2021-01-18 10:12:46 R-modePrioManu all
2021-01-18 10:12:46 R-modePrioParty all
2021-01-18 10:12:46 R-nightTemp 17 C
2021-01-18 10:12:46 R-noMinMax4Manu off
2021-01-18 10:12:46 R-regAdaptive on
2021-01-18 10:12:46 R-showInfo time
2021-01-18 10:12:42 R-sign off
2021-01-18 10:12:46 R-tempOffset 0.0K
2021-01-18 10:12:46 R-valveOffsetRt 0 %
2021-01-18 10:12:46 R-winOpnBoost off
2022-02-12 18:54:43 R_0_tempListSat 07:00 18.0 23:00 21.5 24:00 18.0
2022-02-12 18:54:43 R_1_tempListSun 07:00 18.0 23:00 21.5 24:00 18.0
2022-02-12 18:54:43 R_2_tempListMon 07:00 18.0 23:00 21.5 24:00 18.0
2022-02-12 18:54:43 R_3_tempListTue 07:00 18.0 23:00 21.5 24:00 18.0
2022-02-12 18:54:43 R_4_tempListWed 07:00 18.0 23:00 21.5 24:00 18.0
2022-02-12 18:54:43 R_5_tempListThu 07:00 18.0 23:00 21.5 24:00 18.0
2022-02-12 18:54:43 R_6_tempListFri 07:00 18.0 23:00 21.5 24:00 18.0
2022-02-12 18:54:43 R_tempList_State verified
2022-02-12 18:54:39 RegL_01. 00:00 08:00
2022-02-12 18:54:43 RegL_07. 00:00 01:2A 02:22 03:09 04:3D 05:18 06:03 07:00 08:16 09:07 0A:30 0B:00 0C:64 0D:0F 0E:05 0F:00 10:00 11:00 12:09 13:8E 14:48 15:54 16:57 17:14 18:49 19:20 1A:49 1B:20 1C:45 1D:20 1E:45 1F:20 20:45 21:20 22:45 23:20 24:45 25:20 26:45 27:20 28:45 29:20 2A:45 2B:20 2C:45 2D:20 2E:48 2F:54 30:57 31:14 32:49 33:20 34:49 35:20 36:45 37:20 38:45 39:20 3A:45 3B:20 3C:45 3D:20 3E:45 3F:20 40:45 41:20 42:45 43:20 44:45 45:20 46:45 47:20 48:48 49:54 4A:57 4B:14 4C:49 4D:20 4E:55 4F:14 50:49 51:20 52:45 53:20 54:45 55:20 56:45 57:20 58:45 59:20 5A:45 5B:20 5C:45 5D:20 5E:45 5F:20 60:45 61:20 62:48 63:54 64:57 65:14 66:49 67:20 68:55 69:14 6A:49 6B:20 6C:45 6D:20 6E:45 6F:20 70:45 71:20 72:45 73:20 74:45 75:20 76:45 77:20 78:45 79:20 7A:45 7B:20 7C:48 7D:54 7E:57 7F:14 80:49 81:20 82:55 83:14 84:49 85:20 86:45 87:20 88:45 89:20 8A:45 8B:20 8C:45 8D:20 8E:45 8F:20 90:45 91:20 92:45 93:20 94:45 95:20 96:48 97:54 98:57 99:14 9A:49 9B:20 9C:55 9D:14 9E:49 9F:20 A0:45 A1:20 A2:45 A3:20 A4:45 A5:20 A6:45 A7:20 A8:45 A9:20 AA:45 AB:20 AC:45 AD:20 AE:45 AF:20 B0:48 B1:54 B2:57 B3:14 B4:49 B5:20 B6:55 B7:14 B8:49 B9:20 BA:45 BB:20 BC:45 BD:20 BE:45 BF:20 C0:45 C1:20 C2:45 C3:20 C4:45 C5:20 C6:45 C7:20 C8:45 C9:20 CA:12 CB:21 CC:2D CD:0F CE:1E CF:1E
2022-04-11 21:58:14 ValvePosition 22
2022-04-11 21:58:14 boostTime -
2022-02-12 18:55:44 cfgState TempChk
2022-04-11 15:58:53 commState CMDs_done
2022-04-11 21:58:14 controlMode auto
2022-04-11 21:58:14 desired-temp 21.5
2022-04-11 21:58:14 measured-temp 23.7
2022-04-11 21:58:14 partyEnd -
2022-04-11 21:58:14 partyStart -
2022-04-11 21:58:14 partyTemp -
2022-03-12 07:13:03 recentStateType ack
2022-04-11 21:58:14 state T: 23.7 desired: 21.5 valve: 22
helper:
peerFriend peerRTteam2
peerIDsState complete
peerOpt p:thermostat
regLst 1,7
cmds:
TmplKey :no:1649681887.56634
TmplTs 1649681887.56634
cmdKey 1:0:0::HM_Hz_WZ:0095:04:
cmdLst:
burstXmit noArg
clear [({msgErrors}|msgEvents|rssi|attack|trigger|register|oldRegs|readings|all)]
controlManu (on|off|5.0..30.0;0.5)
controlMode (auto|manual|boost|day|night)
controlParty -temp- -startDate- -startTime- -endDate- -endTime-
desired-temp (on|off|5.0..30.0;0.5)
getConfig noArg
getRegRaw (List0|List1|List2|List3|List4|List5|List6|List7) [-peerChn-]
inhibit [(on|{off})]
peerBulk -peer1,peer2,...- [({set}|unset)]
peerSmart -peerOpt-
regBulk -list-.-peerChn- -addr1:data1- [-addr2:data2-]...
regSet [(prep|{exec})] -regName- -value- [-peerChn-]
sign [(on|{off})]
sysTime noArg
tempListFri [(prep|{exec})] -HH:MM- -temp- [...]
tempListMon [(prep|{exec})] -HH:MM- -temp- [...]
tempListSat [(prep|{exec})] -HH:MM- -temp- [...]
tempListSun [(prep|{exec})] -HH:MM- -temp- [...]
tempListThu [(prep|{exec})] -HH:MM- -temp- [...]
tempListTmpl [({verify}|restore)] [[-file-:]-templateName-]
tempListTue [(prep|{exec})] -HH:MM- -temp- [...]
tempListWed [(prep|{exec})] -HH:MM- -temp- [...]
tempTmplSet -tempTmpl-
tplDel -tplDel-
tplSet_0 -tplChan-
lst:
condition slider,0,1,255
peer
peerOpt HM_2FAF55_ClimaTeam,HM_44017C_ClimaTeam,HM_6A1B20_ClimaTeam,HM_6A2032_ClimaTeam
tplChan
tplDel
tplPeer
rtrvLst:
cmdList [({short}|long)]
deviceInfo [({short}|long)]
list [({normal}|full)]
param -param-
reg -addr- -list- [-peerChn-]
regList noArg
regTable noArg
regVal -addr- -list- [-peerChn-]
saveConfig [-filename-]
tplInfo noArg
expert:
def 1
det 0
raw 1
tpl 0
peerIDsH:
00000000 broadcast
role:
chn 1
shRegR:
07 00
tmpl:
Attributes:
DbLogExclude .*
DbLogInclude desired-temp,measured-temp,ValvePosition
alias Wohnzimmer
event-min-interval desired-temp:900,measured-temp:900,ValvePosition:900
group Heizung
model HM-CC-RT-DN
peerIDs 00000000
room Heizung
userattr weekprofile
verbose 5
weekprofile Plan_WZ
Auch ein Verbose von 5 auf dem Device gibt mir nicht viel Aufschluss:
2022.04.11 15:08:06 5: CUL_HM set HM_Hz_WZ_Clima ?
2022.04.11 15:08:06 5: CUL_HM set HM_Hz_WZ ?
Hat jemand eine Idee wie ich den Fehler besser eingrenzen kann?
PS: Wenn morgen keine im Haus ist versuche ich das Verhalten mal mit den anderen Thermostaten nachzustellen.
liest sich wie, als hättest einen Pi -> dessen Netzgerät abnippelt
5V Spannung messen, sollte 5,1 Volt sein
ZitatHat jemand eine Idee wie ich den Fehler besser eingrenzen kann?
0. ist fhem up-to-date?
1. verbose=5 in den homematic devices bringt sicher nichts, wieder löschen.
2. welchen befehl nutzt du genau? passiert es dabei immer?
3. zeig ein list HM_Hz_WZ.
4. wirklich nur ein fhem absturz, oder der ganze pi?
5. was steht in fhem.log vor dem absturz?
6. "attr global verbose 5" setzen, dann den absturz provozieren und log posten.
0. ist fhem up-to-date?
- ja raspian und fhem sind aktuell
1. verbose=5 in den homematic devices bringt sicher nichts, wieder löschen.
- wieder gelöscht
2. welchen befehl nutzt du genau? passiert es dabei immer?
set HM_Hz_WZ_Clima desired-temp XX°C ist bei den HM Modulen als Dropdown im Device zu sehen.
3. zeig ein list HM_Hz_WZ.
Internals:
CUL_0_MSGCNT 12
CUL_0_RAWMSG A0FF386106A20270000000AACED101900::-62:CUL_0
CUL_0_RSSI -62
CUL_0_TIME 2022-04-12 16:30:04
DEF 6A2027
FUUID 5cd59b87-f33f-aed9-45a3-0feb8cf979f45fb1
IODev CUL_0
LASTInputDev CUL_0
MSGCNT 12
NAME HM_Hz_WZ
NR 966
NTFY_ORDER 48-HM_Hz_WZ
STATE CMDs_pending
TYPE CUL_HM
channel_01 HM_Hz_WZ_Weather
channel_02 HM_Hz_WZ_Climate
channel_03 HM_Hz_WZ_WindowRec
channel_04 HM_Hz_WZ_Clima
channel_05 HM_Hz_WZ_ClimaTeam
channel_06 HM_Hz_WZ_remote
disableNotifyFn 1
lastMsg No:F3 - t:10 s:6A2027 d:000000 0AACED101900
protLastRcv 2022-04-12 16:30:04
protRcv 12 last_at:2022-04-12 16:30:04
rssi_at_CUL_0 cnt:12 min:-63 max:-62 avg:-62.41 lst:-62
READINGS:
2022-04-12 16:12:51 Activity alive
2022-03-12 07:13:02 CommandAccepted yes
2021-01-18 10:06:58 D-firmware 1.5
2021-01-18 10:06:58 D-serialNr PEQ1191523
2022-04-12 16:02:49 IODev CUL_0
2022-02-12 18:54:37 PairedTo 0xF11034
2021-01-18 10:12:40 R-backOnTime 10 s
2021-01-18 10:12:40 R-burstRx on
2021-01-18 10:12:40 R-cyclicInfoMsg on
2021-01-18 10:12:40 R-cyclicInfoMsgDis 0
2021-01-18 10:12:40 R-pairCentral 0xF11034
2022-02-12 18:54:37 RegL_00. 00:00 01:01 02:01 09:01 0A:F1 0B:10 0C:34 0E:0A 0F:01 11:00 12:15 16:01 18:00 19:00 1A:00
2022-02-13 21:51:18 RegL_07.
2022-04-12 16:30:04 actuator 25
2022-04-12 16:30:04 battery ok
2022-04-12 16:30:04 batteryLevel 3.1
2022-02-12 18:55:44 cfgState PairMism
2022-04-12 15:45:01 commState CMDs_pending
2022-04-12 16:30:04 desired-temp 21.5
2022-04-12 16:30:04 measured-temp 23.7
2022-04-12 16:30:04 motorErr ok
2022-02-12 18:52:12 powerOn 2022-02-12 18:52:12
2022-02-12 18:52:12 recentStateType info
2022-04-12 15:45:01 state CMDs_pending
2022-04-12 14:44:14 time-request -
helper:
HM_CMDNR 243
lastMsgTm 1649773804.19843
mId 0095
peerFriend -
peerOpt -:thermostat
regLst 0
rxType 140
supp_Pair_Rep 0
cmds:
TmplKey :no:1649772172.62677
TmplTs 1649772172.62677
cmdKey 0:1:0::HM_Hz_WZ:0095:01:
cmdLst:
assignHmKey noArg
burstXmit noArg
clear [({msgErrors}|msgEvents|rssi|attack|trigger|register|oldRegs|readings|all)]
deviceRename -newName-
fwUpdate -filename- [-bootTime-]
getConfig noArg
getDevInfo noArg
getRegRaw (List0|List1|List2|List3|List4|List5|List6|List7) [-peerChn-]
inhibit [(on|{off})]
raw -data- [...]
regBulk -list-.-peerChn- -addr1:data1- [-addr2:data2-]...
regSet [(prep|{exec})] -regName- -value- [-peerChn-]
reset noArg
sysTime noArg
tplDel -tplDel-
tplSet_0 -tplChan-
unpair noArg
lst:
condition slider,0,1,255
peer
peerOpt
tplChan
tplDel
tplPeer
rtrvLst:
cmdList [({short}|long)]
deviceInfo [({short}|long)]
list [({normal}|full)]
param -param-
reg -addr- -list- [-peerChn-]
regList noArg
regTable noArg
regVal -addr- -list- [-peerChn-]
saveConfig [-filename-]
tplInfo noArg
expert:
def 1
det 0
raw 1
tpl 0
io:
flgs 0
newChn +6A2027,00,00,00
nextSend 1649773804.28126
rxt 2
vccu
p:
6A2027
00
00
00
prefIO:
mRssi:
mNo F3
io:
CUL_0:
-58
-58
peerIDsH:
prt:
bErr 0
sProc 0
q:
qReqConf
qReqStat
role:
dev 1
prs 1
rssi:
at_CUL_0:
avg -62.4166666666667
cnt 12
lst -62
max -62
min -63
shRegW:
07 04
tmpl:
Attributes:
DbLogExclude .*
IODev CUL_0
actCycle 000:10
actStatus alive
alias Wohnzimmer
autoReadReg 4_reqStatus
event-on-change-reading desired-temp,measured-temp,ValvePosition
expert defReg,rawReg
firmware 1.5
model HM-CC-RT-DN
room Heizung
serialNr PEQ1191523
subType thermostat
webCmd getConfig:clear msgEvents:burstXmit
4. wirklich nur ein fhem absturz, oder der ganze pi?
- nur fhem, der pi läuft seit 34 Tagen laut "top"
5. was steht in fhem.log vor dem absturz?
Ich hab die Temperatur verändert und dann ist Fhem langsam abgestürzt, die Auslastung vom Pi ging hoch und nach ca 10 min gabs einen Fhem neustart.
Bei der Recherche zum Fehler fiel mir auf, dass der Fehler nur bei dem Thermostat im Wohnzimmer auftritt.
Die einzige Sonderfunktion im Wohnzimmer das über den Reg Befehl die Bedieung am Thermostat abgeschaltet ist.
Nicht logisch aus meiner Sicht.
Ich finde ja ein fhem.log zum Absturzzeitpunkt, mit verbose 5, wo der Neustart nicht mal zu sehen ist, nicht besonders informativ.
Interessant ist, dass Deine Uhr rückwärts läuft!?
Jetzt ist der Beweis dafür leider weg?
Da sind zum einen viele Perl-Prozesse zu sehen, und das Ding fängt an zu swapen...
Glaskugel sagt: Der Rechner an sich ist am oberen Ende der Belastungsfähigkeit (auch wegen CUL_HM/commState), vermutlich iVm. dem Thema "unsaubere" Event-Handler (kein NOTIFYDEV), und PRESENCE und/oder Datenbankoperationen bringt dann das Fass zum überlaufen...?
@tfriedrich85: Wenn das zutrifft, ist das ist ein "Klon" von dem, was wir in jüngster häufiger hatten, bitte erst mal die betreffenden Threads suchen.
Ich stimme Beta-User total zu. ein kswapd der 33 oder 100% CPU braucht ist "nicht gut".
Und der SWAP ist auch zu 100% gefüllt .....
das log ist schon seltsam und vermutlich nicht vollständig. vom cul ist bereits 4min vor ende schon nichts mehr zu sehen.
ist das wirklich das fhem.log file mit einem editor geöffnet?
die vielen fhem instanzen sind auch seltsam.
falls es alles forks einer parent instanz wären, müssten die doch wieder beendet werden und im log sollten "cannot allocate memory" meldungen auftauchen, bevor das os fhem killt. oder nicht?
probiere zb mal als notfallpflaster: "attr global blockingCallMax 5"
Zitat
blockingCallMax
Limit the number of parallel running processes started by the BlockingCall FHEM helper routine. Useful on limited hardware, default is 32. If the limit is reached, further calls are delayed.
nun, da würde ich nun erst einmal die blockingcalls tracken. diese sind sowieso kritisch und nicht immer umsichtig implementiert.
Leiter gibt es das nicht auf System-ebene. Daher habe ich in HMinfo eingebaut (Achtung Bug!)
get hm showChilds hm
ich haben "hm" und "all" vertauscht - das ist der bug. Werde ich gleich korrigieren.
es sollten immer nur einzelne prozesse geforkt werden (also blocking call). Wenn du einmal mehr aus 4 siehst melde dies.
Eingenlich sollte der Kernel hier mehr support liefern - auch mein System ist schon hängen geblieben nach startenneuer FHEM services - bis ich die blockings eliminiert habe
Zitat von: Beta-User am 12 April 2022, 16:59:28
Da sind zum einen viele Perl-Prozesse zu sehen, und das Ding fängt an zu swapen...
Glaskugel sagt: Der Rechner an sich ist am oberen Ende der Belastungsfähigkeit (auch wegen CUL_HM/commState), vermutlich iVm. dem Thema "unsaubere" Event-Handler (kein NOTIFYDEV), und PRESENCE und/oder Datenbankoperationen bringt dann das Fass zum überlaufen...?
@tfriedrich85: Wenn das zutrifft, ist das ist ein "Klon" von dem, was wir in jüngster häufiger hatten, bitte erst mal die betreffenden Threads suchen.
Danke für die vielen Hinweise, scheinbar gibts da mehrere Baustellen.
@Beta-User: Kannst du mir ein Schlagwort nennen unter dem ich ähnliche Threads oder Fehlerbilder finde?
Was heißt unsaubere Event-Handler in Bezug auf die Thermostate?
Ich hab nochmal - diesmal hoffentlich vollständig - ein Log vor während und nach dem Absturz direkt vom PI geholt (Neustart 22.4. 13:24) und in den Anhang gepackt, vielleicht bringt das mehr Licht ins Dunkel
Zitat von: Otto123 am 12 April 2022, 16:51:12
Ich finde ja ein fhem.log zum Absturzzeitpunkt, mit verbose 5, wo der Neustart nicht mal zu sehen ist, nicht besonders informativ.
Interessant ist, dass Deine Uhr rückwärts läuft!?
Jetzt ist der Beweis dafür leider weg?
Hey Frank
Hey Otto,
ich habe eine neues Fehler Log vor während und nach dem Absturz direkt vom PI geholt (Neustart 22.4. 13:24) und in den Anhang gepackt, vielleicht bringt das mehr Licht ins Dunkel. Die Es kann sein, das die Zeit rückwärts läuft, weil ich die Zeilen aus der Fhem Oberfläche kopiert hahbe und dort ist es so konfiguriert, dass das neuste Ereignis oben steht.
Zitat von: tfriedrich85 am 22 April 2022, 13:16:39
Danke für die vielen Hinweise, scheinbar gibts da mehrere Baustellen.
Ja. angefangen damit, dass das verbose 5-log unglaublich "zäh" ist. Für mich sieht das weiter danach aus, dass FHEM zu "träge" reagiert und daher dann systemd einen Neustart veranlasst. Da scheint
zwischen
2022.04.22 13:22:58 5: redefine at command sende as +*00:00:05 {sendeAnAnalog2 (00,1023)}
und dem den eigentlichen Neustart vermutlich ziemlich genau bestimmenden
2022.04.22 13:23:30 3: WEB: port 8083 openedeinfach "nichts" passiert zu sein
Zitat
@Beta-User: Kannst du mir ein Schlagwort nennen unter dem ich ähnliche Threads oder Fehlerbilder finde?
Wie viele brauchst du denn:
Zitat von: Beta-User am 12 April 2022, 16:59:28
CUL_HM/commState
(kein NOTIFYDEV),
und PRESENCE
Zitat
Was heißt unsaubere Event-Handler in Bezug auf die Thermostate?
Irrtum: Es geht nicht speziell um "Thermostate". Die haben nur "viele Kanäle" und sind daher iV. dem ersten Schlagwort besonders "gefährlich" (weil die Auswirkungen sich entsprechend vervielfachen).
Über das erste Suchwort "commState" wirst du auch weitere Hinweise finden. Bitte erst selbst suchen, unter drei selbst gefundenen und hier geposteten "falschen" positives fange ich nicht selbst an zu suchen.
Zitat von: Beta-User am 23 April 2022, 18:57:47
dass FHEM zu "träge" reagiert und daher dann systemd einen Neustart veranlasst.
Müsste man doch sehen mit journalctl oder im syslog?
Auf alle Fälle gehört verbose 5 aus. Das ist eine Zumutung - fürs system und für uns ;) Fehler sieht man auch ohne verbose 5
Zitat von: Otto123 am 23 April 2022, 21:23:10
Müsste man doch sehen mit journalctl oder im syslog?
Schon. Hat nur bisher keiner explizit danach gefragt, oder?
Aber solange "commState" im (verbose 5-log...) auftaucht, braucht man mit einiger Wahrscheinlichkeit kaum vertiefter nachbohren :P .
ok ich versuch es mal:
sudo journalctl|grep "fhem.service: Failed"
@ tfriedrich85
Gibt es da Einträge im Log?
sudo journalctl|grep "fhem.service: Failed"
habe ich allerding bloß simuliert getestet sudo kill -6 ...
bzw:
sudo pkill -f -6 fhem.pl
Zitat von: Otto123 am 23 April 2022, 22:45:45
ok ich versuch es mal:
sudo journalctl|grep "fhem.service: Failed"
@ tfriedrich85
Gibt es da Einträge im Log?
sudo journalctl|grep "fhem.service: Failed"
habe ich allerding bloß simuliert getestet sudo kill -6 ...
bzw:
sudo pkill -f -6 fhem.pl
Hallo Otto,
ja, mit
Mär 28 16:43:35 raspberrypi systemd[1]: fhem.service: Failed with result 'timeout'.
oder
Apr 21 16:01:14 raspberrypi systemd[1]: fhem.service: Failed with result 'signal'.
und mit
sudo pkill -f -6 fhem.pl erscheint "Abgebrochen"
ist jetzt nicht so häufig wie vermutet?
was steht denn davor und danach?
sudo journalctl|grep -C 10 "fhem.service: Failed"
interessanter finde ich ja den zeitraum vor dem gezeigten fhem restart aus dem log => Neustart 22.4. 13:24
also vom zeitpunkt des setzens von desired-temp bis zum neustart.
dieser restart erzeugt scheinbar kein "failure" ereignis.