Absturz bei Temperaturveränderung

[tfriedrich85]

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!

Code Auswählen Erweitern

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:

Code Auswählen Erweitern

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.

[LuckyDay]

liest sich wie, als hättest einen Pi -> dessen Netzgerät abnippelt
5V Spannung messen, sollte 5,1 Volt sein

[frank]

Hat 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.

[tfriedrich85]

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.

Code Auswählen Erweitern

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.

[Otto123]

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?

[Beta-User]

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.

[Wernieman]

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 .....

[frank]

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"

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.

[martinp876]

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!)

Code Auswählen Erweitern

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

[tfriedrich85]

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

[tfriedrich85]

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.

[Beta-User]

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

Code Auswählen Erweitern

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

Code Auswählen Erweitern

2022.04.22 13:23:30 3: WEB: port 8083 opened
einfach "nichts" passiert zu sein

@Beta-User: Kannst du mir ein Schlagwort nennen unter dem ich ähnliche Threads oder Fehlerbilder finde?

Wie viele brauchst du denn:

CUL_HM/commState

(kein NOTIFYDEV),
und PRESENCE

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.

[Otto123]

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

[Beta-User]

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 .

[Otto123]

ok ich versuch es mal:

Code Auswählen Erweitern

sudo journalctl|grep "fhem.service: Failed"
@ tfriedrich85
Gibt es da Einträge im Log?

Code Auswählen Erweitern

sudo journalctl|grep "fhem.service: Failed"
habe ich allerding bloß simuliert getestet sudo kill -6 ...
bzw:

Code Auswählen Erweitern

sudo pkill -f -6 fhem.pl