Sporadisch FHEM-Absturz durch Ausschalten eines verbundenen Clients

TheTrumpeter · 17 Oktober 2025, 07:04:36

Gestern hat's dann nicht mehr geklappt, hier nun die letzten Ausgaben. Insgesamt gab's gestern 3 Vorkommnisse, wobei nur beim 1. Mal auch der eingangs verdächtigte Stand-PC daheim eingeschaltet war. In der Ausgabe finde ich dazu aber nichts.

Ich habe die Ausgaben verglichen, am Ende bleibt immer der WEBphone-Requst als letzter Eintrag stehen, was ich grundsätzlich komisch finde, da ich von genau diesem Gerät sehr häufig zugreife. Warum's da grad gestern 3x das Problem gab ist mir nicht ganz klar.
MÖGLICHERWEISE ist der Absturz immer dann aufgetreten, wenn ich vom LTE- ins WLAN gewechselt bin, d.h. die Seitenaktualisierung aus dem LTE-Netz getriggert habe, kurz darauf (oder genau dabei) aber ins WLAN gewechselt bin.

Absturz 1 (nach über 3 Wochen unauffälligem Betrieb):

Code Auswählen

2025.10.16 09:15:24 4: myHuawei: CreateDataObjects assigns value Netz verbunden to Device_status
2025.10.16 09:15:24 5: myHuawei: CreateParseInfoCache called
2025.10.16 09:15:24 5: myHuawei: CreateDataObjects unpacked 0000 with n to 0
2025.10.16 09:15:24 5: myHuawei: perl expression eval evaluated package main; my @val = @{$oRef->{'%val'}};$val/1 to 0
2025.10.16 09:15:24 4: myHuawei: CreateDataObjects assigns value 0 to Faultcode
2025.10.16 09:15:24 5: myHuawei: CreateParseInfoCache called
2025.10.16 09:15:24 5: myHuawei: CreateDataObjects unpacked 0000 with n to 0
2025.10.16 09:15:24 5: myHuawei: perl expression eval evaluated package main; my @val = @{$oRef->{'%val'}};$val/1 to 0
2025.10.16 09:15:24 4: myHuawei: CreateDataObjects assigns value 0 to Alarm_1
2025.10.16 09:15:24 5: myHuawei: CreateParseInfoCache called
2025.10.16 09:15:24 5: myHuawei: CreateDataObjects unpacked 0000 with n to 0
2025.10.16 09:15:24 5: myHuawei: perl expression eval evaluated package main; my @val = @{$oRef->{'%val'}};$val/1 to 0
2025.10.16 09:15:24 4: myHuawei: CreateDataObjects assigns value 0 to Alarm_2
2025.10.16 09:15:24 5: myHuawei: CreateParseInfoCache called
2025.10.16 09:15:24 5: myHuawei: CreateDataObjects unpacked 0000 with n to 0
2025.10.16 09:15:24 5: myHuawei: perl expression eval evaluated package main; my @val = @{$oRef->{'%val'}};$val/1 to 0
2025.10.16 09:15:24 4: myHuawei: CreateDataObjects assigns value 0 to Alarm_3
2025.10.16 09:15:24 5: myHuawei: ParseDataString created 19 readings, errcode undef
2025.10.16 09:15:24 4: myHuawei: HandleResponse done, current frame / read buffer: 00f4000000a90103a6000000000000000000000000000087e51999019b199900001989019a198900000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000014cb0fde0fd40fdd09260923092d00001d3b00001d4100001d2b000014740000146a0000000403e81389265a01900bb802000000, id 1, fCode 3, tid 244,
request: id 1, read fc 3 h32008, len 83, tid 244, master device myHuawei, reading Alarm_1 (getUpdate for Alarm_1 len 83), queued 0.89 secs ago, sent 0.88 secs ago,
response: id 1, fc 3, h32008, len 83, values 000000000000000000000000000087e51999019b199900001989019a198900000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000014cb0fde0fd40fdd09260923092d00001d3b00001d4100001d2b000014740000146a0000000403e81389265a01900bb802000000
2025.10.16 09:15:24 5: myHuawei: ResetExpect for HandleResponse from response to idle
2025.10.16 09:15:24 5: myHuawei: StartQueueTimer called from HandleResponse sets internal timer to process queue in 0.000 seconds
2025.10.16 09:15:24 5: myHuawei: DropFrame called from ReadFn - drop 00f4000000a90103a6000000000000000000000000000087e51999019b199900001989019a198900000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000014cb0fde0fd40fdd09260923092d00001d3b00001d4100001d2b000014740000146a0000000403e81389265a01900bb802000000
2025.10.16 09:15:24 5: myHuawei: readFn end buffer:  mode master, expect idle
2025.10.16 09:15:24 5: Cmd: >setreading myHuawei Eigennutzung_momentan {(([myHuawei:Active_Power:d]<[SmartMeterRestAPI:Momentanleistungsbedarf:d])?([myHuawei:Active_Power:d]):([SmartMeterRestAPI:Momentanleistungsbedarf:d]))} W<
2025.10.16 09:15:24 5: Starting notify loop for myHuawei, 1 event(s), first is Eigennutzung_momentan: 2842 W
2025.10.16 09:15:24 5: statistics PVAnlage.Statistik: DoStatistics.455 Assigned reading 'Ersparnis_Eigennutzung' from attribute 'deltaReadings' to statistic type 2.
2025.10.16 09:15:24 5: statistics PVAnlage.Statistik: DoStatistics.455 Assigned reading 'Ersparnis_Einspeisung' from attribute 'deltaReadings' to statistic type 2.
2025.10.16 09:15:24 5: statistics PVAnlage.Statistik: DoStatistics.455 Assigned reading 'Accumulated_energy_yield' from attribute 'deltaReadings' to statistic type 2.
2025.10.16 09:15:24 4: statistics PVAnlage.Statistik: doStatisticDelta.778 Calculating delta statistics for 'myHuawei:Ersparnis_Eigennutzung = 2179.372028342'
2025.10.16 09:15:24 5: statistics PVAnlage.Statistik: doStatisticDelta.882 Set '.myHuawei:Ersparnis_Eigennutzung'='LastValue: 2179.372028342 ShowDate: 0 DecPlaces: 9'
2025.10.16 09:15:24 5: statistics PVAnlage.Statistik: doStatisticDelta.888 Set 'statErsparnis_Eigennutzung'='Hour: 0.211863132 Day: 0.556531966 Month: 22.722844371 Year: 867.330851059'
2025.10.16 09:15:24 4: statistics PVAnlage.Statistik: doStatisticDelta.778 Calculating delta statistics for 'myHuawei:Ersparnis_Einspeisung = 3549.2036394275'
2025.10.16 09:15:24 5: statistics PVAnlage.Statistik: doStatisticDelta.882 Set '.myHuawei:Ersparnis_Einspeisung'='LastValue: 3549.2036394275 ShowDate: 0 DecPlaces: 10'
2025.10.16 09:15:24 5: statistics PVAnlage.Statistik: doStatisticDelta.888 Set 'statErsparnis_Einspeisung'='Hour: 0.0239400000 Day: 0.1210500000 Month: 20.1858300000 Year: 861.5289450002'
2025.10.16 09:15:24 4: statistics PVAnlage.Statistik: doStatisticDelta.778 Calculating delta statistics for 'myHuawei:Accumulated_energy_yield = 50958.66'
2025.10.16 09:15:24 5: statistics PVAnlage.Statistik: doStatisticDelta.882 Set '.myHuawei:Accumulated_energy_yield'='LastValue: 50958.66 ShowDate: 0 DecPlaces: 2'
2025.10.16 09:15:24 5: statistics PVAnlage.Statistik: doStatisticDelta.888 Set 'statAccumulated_energy_yield'='Hour: 1.31 Day: 4.64 Month: 528.50 Year: 18257.79'
2025.10.16 09:15:24 5: Starting notify loop for PVAnlage.Statistik, 1 event(s), first is Updated stats for: myHuawei
2025.10.16 09:15:24 5: End notify loop for PVAnlage.Statistik
2025.10.16 09:15:24 5: statistics PVAnlage.Statistik: Notify.301 Notification of 'myHuawei' received. Update statistics.
2025.10.16 09:15:24 5: End notify loop for myHuawei
2025.10.16 09:15:24 5: Cmd: >setreading myHuawei Ersparnis_Einspeisung {(([SmartMeterRestAPI:Einspeisung_Tag:d])*[Energiepreise:Strom_Einspeisung:d]+[myHuawei:Ersparnis_Einspeisung_bisgestern:d])} EUR<
2025.10.16 09:15:24 5: Cmd: >sleep 0 quiet<
2025.10.16 09:15:24 5: myHuawei: ProcessRequestQueue called from Fhem internal timer as queue:myHuawei, qlen 7, request: request: id 1, read fc 3 h32016, len 6, tid 254, master device myHuawei, reading PV1_voltage (getUpdate for PV1_voltage len 6), queued 0.90 secs ago
2025.10.16 09:15:24 5: myHuawei: checkDelays clientSwitchDelay is not relevant
2025.10.16 09:15:24 5: myHuawei: checkDelays busDelayRead is not required
2025.10.16 09:15:24 5: myHuawei: checkDelays sendDelay, last send to same device was 0.895 secs ago, required delay is 0.1
2025.10.16 09:15:24 5: myHuawei: checkDelays commDelay, last communication with same device was 0.051 secs ago, required delay is 0.1
2025.10.16 09:15:24 4: myHuawei: checkDelays found commDelay not over, set timer to try again in 0.049
2025.10.16 09:15:24 4: ESPEasy myESPBridge_10.0.0.95_54049: Received content length ok
2025.10.16 09:15:24 5: ESPEasy ESPEasy_SprinklerControl_Ventilschacht: Received: SprinklerControl_Ventilschacht::10.0.0.95::1::0::1::i||unit||0||0|||i||sleep||0||0|||i||build||21186||0|||i||build_git||mega-20250430||0|||i||build_notes|| - Mega32||0|||i||version||3||0|||i||node_type_id||33||0|||r||Feuchtigkeit||99.9||2|||r||Temperatur||9.8||2
2025.10.16 09:15:24 4: ESPEasy ESPEasy_SprinklerControl_Ventilschacht: Feuchtigkeit: 99.9
2025.10.16 09:15:24 4: ESPEasy ESPEasy_SprinklerControl_Ventilschacht: Temperatur: 9.8
2025.10.16 09:15:24 5: ESPEasy ESPEasy_SprinklerControl_Ventilschacht: Internals: unit:0 sleep:0 build:21186 build_git:mega-20250430 build_notes: - Mega32 version:3 node_type_id:ESP Easy 32
2025.10.16 09:15:24 5: Cmd: >setreading SmartMeterRestAPI Zaehlerstand_Eigennutzung {([myHuawei:Accumulated_energy_yield:d]-[SmartMeterRestAPI:Zaehlerstand_Einspeisung:d])} kWh<
2025.10.16 09:15:24 4: Connection accepted from WEBphone_::ffff:194.39.218.13_60651
2025.10.16 09:15:24 5: myHuawei: ProcessRequestQueue called from Fhem internal timer as queue:myHuawei, qlen 7, request: request: id 1, read fc 3 h32016, len 6, tid 254, master device myHuawei, reading PV1_voltage (getUpdate for PV1_voltage len 6), queued 1.20 secs ago
2025.10.16 09:15:24 5: myHuawei: checkDelays busDelayRead is not required
2025.10.16 09:15:24 5: myHuawei: checkDelays sendDelay, last send to same device was 1.189 secs ago, required delay is 0.1
2025.10.16 09:15:24 5: myHuawei: checkDelays clientSwitchDelay is not relevant
2025.10.16 09:15:24 5: myHuawei: checkDelays commDelay, last communication with same device was 0.345 secs ago, required delay is 0.1
2025.10.16 09:15:24 4: myHuawei: ProcessRequestQueue (V4.5.6 - 7.11.2023) qlen 7, sending 00fe0000000601037d100006 via 10.0.0.94:502, read buffer empty,
request: id 1, read fc 3 h32016, len 6, tid 254, master device myHuawei, reading PV1_voltage (getUpdate for PV1_voltage len 6), queued 1.20 secs ago
2025.10.16 09:15:24 5: myHuawei: Send called from ProcessRequestQueue
2025.10.16 09:15:24 5: DevIo_SimpleWrite myHuawei: 00fe0000000601037d100006
2025.10.16 09:15:24 5: myHuawei: StartQueueTimer called from ProcessRequestQueue sets internal timer to process queue in 1.000 seconds
2025.10.16 09:15:28 5: GET /fhem?XHR=1&inform=type%3Dstatus%3Bfilter%3Droom%3DStrom%3Bsince%3D1760598915.8880098%3Bfmt%3DJSON&fw_id=1760587126.90304&timestamp=1760598924249 HTTP/1.1
Host: <entfernt>:8084
Accept: */*
Sec-Fetch-Site: same-origin
Sec-Fetch-Mode: cors
User-Agent: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/18.7 Mobile/15E148 Safari/604.1
Referer: https://<entfernt>:8084/fhem?room=Strom
Sec-Fetch-Dest: empty
Authorization: Basic <entfernt>
Accept-Language: de-DE,de;q=0.9
Priority: u=3, i
Accept-Encoding: gzip, deflate, br
Cookie: dashboard_activetab=2
Connection: keep-alive
2025.10.16 09:15:28 4: WEBphone_::ffff:194.39.218.13_60651 GET /fhem?XHR=1&inform=type%3Dstatus%3Bfilter%3Droom%3DStrom%3Bsince%3D1760598915.8880098%3Bfmt%3DJSON&fw_id=1760587126.90304&timestamp=1760598924249; BUFLEN:0
Killed

Absturz 2 (kurz nach dem Neustart, siehe Zeitstempel):

Code Auswählen

2025.10.16 09:48:49 5: myHuawei: ResetExpect for HandleResponse from response to idle
2025.10.16 09:48:49 5: myHuawei: StartQueueTimer called from HandleResponse sets internal timer to process queue in 0.000 seconds
2025.10.16 09:48:49 5: myHuawei: DropFrame called from ReadFn - drop 005d0000000701030400001a1d
2025.10.16 09:48:49 5: myHuawei: readFn end buffer:  mode master, expect idle
2025.10.16 09:48:49 5: myHuawei: ProcessRequestQueue called from Fhem internal timer as queue:myHuawei, qlen 2, request: request: id 1, read fc 3 h32086, len 1, tid 25, master device myHuawei, reading Efficiency (getUpdate for Efficiency len 1), queued 4.49 secs ago
2025.10.16 09:48:49 5: myHuawei: checkDelays busDelayRead is not required
2025.10.16 09:48:49 5: myHuawei: checkDelays sendDelay, last send to same device was 0.171 secs ago, required delay is 0.1
2025.10.16 09:48:49 5: myHuawei: checkDelays clientSwitchDelay is not relevant
2025.10.16 09:48:49 5: myHuawei: checkDelays commDelay, last communication with same device was 0.006 secs ago, required delay is 0.1
2025.10.16 09:48:49 4: myHuawei: checkDelays found commDelay not over, set timer to try again in 0.094
2025.10.16 09:48:49 5: myHuawei: ProcessRequestQueue called from Fhem internal timer as queue:myHuawei, qlen 2, request: request: id 1, read fc 3 h32086, len 1, tid 25, master device myHuawei, reading Efficiency (getUpdate for Efficiency len 1), queued 4.59 secs ago
2025.10.16 09:48:49 5: myHuawei: checkDelays commDelay, last communication with same device was 0.102 secs ago, required delay is 0.1
2025.10.16 09:48:49 5: myHuawei: checkDelays sendDelay, last send to same device was 0.267 secs ago, required delay is 0.1
2025.10.16 09:48:49 5: myHuawei: checkDelays clientSwitchDelay is not relevant
2025.10.16 09:48:49 5: myHuawei: checkDelays busDelayRead is not required
2025.10.16 09:48:49 4: myHuawei: ProcessRequestQueue (V4.5.6 - 7.11.2023) qlen 2, sending 00190000000601037d560001 via 10.0.0.94:502, read buffer empty,
request: id 1, read fc 3 h32086, len 1, tid 25, master device myHuawei, reading Efficiency (getUpdate for Efficiency len 1), queued 4.59 secs ago
2025.10.16 09:48:49 5: myHuawei: Send called from ProcessRequestQueue
2025.10.16 09:48:49 5: DevIo_SimpleWrite myHuawei: 00190000000601037d560001
2025.10.16 09:48:49 5: myHuawei: StartQueueTimer called from ProcessRequestQueue sets internal timer to process queue in 1.000 seconds
2025.10.16 09:48:49 4: Connection accepted from WEBphone_::ffff:194.39.218.13_54153
2025.10.16 09:48:50 4: Connection accepted from WEBphone_::ffff:194.39.218.13_54154
2025.10.16 09:48:50 5: myHuawei: readFn buffer: 0019000000050103022663 mode master, expect response
2025.10.16 09:48:50 5: myHuawei: ParseFrameStart called from ReadFn protocol TCP expecting id 1
2025.10.16 09:48:50 4: myHuawei: ParseFrameStart (TCP, master) extracted id 1, fCode 3, tid 25, dlen 5 and potential data 022663
2025.10.16 09:48:50 5: myHuawei: HandleResponse called from ReadFn
2025.10.16 09:48:50 5: myHuawei: HandleResponse is now creating response hash, masterHash is HASH(0x55af532e58)
2025.10.16 09:48:50 5: myHuawei: HandleResponse is now calling ParseResponse, masterHash is HASH(0x55af532e58)
2025.10.16 09:48:50 5: myHuawei: ParseResponse called from HandleResponse, fc 3
2025.10.16 09:48:50 5: myHuawei: now parsing response data objects, master is myHuawei relay is undefined
2025.10.16 09:48:50 5: myHuawei: ParseDataString called from HandleResponse with data hex 2663, type h, adr 32086, op read
2025.10.16 09:48:50 5: myHuawei: SplitDataString called from ParseDataString with data hex 2663, type h, adr 32086, valuesLen 1, op read
2025.10.16 09:48:50 5: myHuawei: CreateDataObjects called from ParseDataString with objList h32086
2025.10.16 09:48:50 5: myHuawei: CreateDataObjects sortedList h32086
2025.10.16 09:48:50 5: myHuawei: CreateParseInfoCache called
2025.10.16 09:48:50 5: myHuawei: CreateDataObjects unpacked 2663 with n! to 9827
2025.10.16 09:48:50 5: myHuawei: perl expression eval evaluated package main; my @val = @{$oRef->{'%val'}};$val/100 to 98.27
2025.10.16 09:48:50 4: myHuawei: CreateDataObjects assigns value 98.27 to Efficiency
2025.10.16 09:48:50 5: myHuawei: ParseDataString created 1 readings, errcode undef
2025.10.16 09:48:50 4: myHuawei: HandleResponse done, current frame / read buffer: 0019000000050103022663, id 1, fCode 3, tid 25,
request: id 1, read fc 3 h32086, len 1, tid 25, master device myHuawei, reading Efficiency (getUpdate for Efficiency len 1), queued 4.88 secs ago, sent 0.29 secs ago,
response: id 1, fc 3, h32086, len 1, values 2663
2025.10.16 09:48:50 5: myHuawei: ResetExpect for HandleResponse from response to idle
2025.10.16 09:48:50 5: myHuawei: StartQueueTimer called from HandleResponse sets internal timer to process queue in 0.000 seconds
2025.10.16 09:48:50 5: myHuawei: DropFrame called from ReadFn - drop 0019000000050103022663
2025.10.16 09:48:50 5: myHuawei: readFn end buffer:  mode master, expect idle
2025.10.16 09:48:50 5: GET /fhem/images/default/fhemicon_darksmall.png HTTP/1.1
Host: <entfernt>:8084
Accept: image/webp,image/avif,image/jxl,image/heic,image/heic-sequence,video/*;q=0.8,image/png,image/svg+xml,image/*;q=0.8,*/*;q=0.5
Sec-Fetch-Site: same-origin
If-None-Match: "1686895353"
Sec-Fetch-Mode: no-cors
User-Agent: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/18.7 Mobile/15E148 Safari/604.1
Referer: https://<entfernt>:8084/fhem?room=Strom
Sec-Fetch-Dest: image
Authorization: Basic <entfernt>
Accept-Language: de-DE,de;q=0.9
Priority: u=5, i
Accept-Encoding: gzip, deflate, br
Cookie: dashboard_activetab=2
Connection: keep-alive
2025.10.16 09:48:50 4: WEBphone_::ffff:194.39.218.13_54153 GET /fhem/images/default/fhemicon_darksmall.png; BUFLEN:0
2025.10.16 09:48:50 4: WEBphone_::ffff:194.39.218.13_54153 => 304 Not Modified
2025.10.16 09:48:50 5: myHuawei: ProcessRequestQueue called from Fhem internal timer as queue:myHuawei, qlen 1, request: request: id 1, read fc 3 h32091, len 2, tid 5, master device myHuawei, reading Startup_Time (getUpdate for Startup_Time len 2), queued 4.88 secs ago
2025.10.16 09:48:50 5: myHuawei: checkDelays commDelay, last communication with same device was 0.008 secs ago, required delay is 0.1
2025.10.16 09:48:50 5: myHuawei: checkDelays clientSwitchDelay is not relevant
2025.10.16 09:48:50 5: myHuawei: checkDelays sendDelay, last send to same device was 0.289 secs ago, required delay is 0.1
2025.10.16 09:48:50 5: myHuawei: checkDelays busDelayRead is not required
2025.10.16 09:48:50 4: myHuawei: checkDelays found commDelay not over, set timer to try again in 0.092
2025.10.16 09:48:50 5: GET /fhem?XHR=1&inform=type%3Dstatus%3Bfilter%3Droom%3DStrom%3Bsince%3D1760600924.27315%3Bfmt%3DJSON&fw_id=1760600925.27317&timestamp=1760600929788 HTTP/1.1
Host: <entfernt>:8084
Accept: */*
Sec-Fetch-Site: same-origin
Sec-Fetch-Mode: cors
User-Agent: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/18.7 Mobile/15E148 Safari/604.1
Referer: https://<entfernt>:8084/fhem?room=Strom
Sec-Fetch-Dest: empty
Authorization: Basic <entfernt>
Accept-Language: de-DE,de;q=0.9
Priority: u=3, i
Accept-Encoding: gzip, deflate, br
Cookie: dashboard_activetab=2
Connection: keep-alive
2025.10.16 09:48:50 4: WEBphone_::ffff:194.39.218.13_54154 GET /fhem?XHR=1&inform=type%3Dstatus%3Bfilter%3Droom%3DStrom%3Bsince%3D1760600924.27315%3Bfmt%3DJSON&fw_id=1760600925.27317&timestamp=1760600929788; BUFLEN:0
Killed

Absturz 3:

Code Auswählen

2025.10.16 11:45:41 5: Triggering MythzDummy_notify
2025.10.16 11:45:41 4: MythzDummy_notify exec {THZ_SplitReadings($NAME,"Dummy",$EVENT,1)}
2025.10.16 11:45:41 5: Cmd: >{THZ_SplitReadings($NAME,"Dummy",$EVENT,1)}<
2025.10.16 11:45:41 5: Cmd: >setreading MythzDummy sDHW sDHW: dhwTemp: 51.6 outsideTemp: 13.1 dhwSetTemp: 10 compBlockTime: 0 out: 0000 heatBlockTime: 0 dhwBoosterStage: 0 pasteurisationMode: 0 dhwOpMode: setback x36: C525<
2025.10.16 11:45:41 5: Starting notify loop for MythzDummy, 1 event(s), first is sDHW: sDHW: dhwTemp: 51.6 outsideTemp: 13.1 dhwSetTemp: 10 compBlockTime: 0 out: 0000 heatBlockTime: 0 dhwBoosterStage: 0 pasteurisationMode: 0 dhwOpMode: setback x36: C525
2025.10.16 11:45:41 5: End notify loop for MythzDummy
2025.10.16 11:45:41 5: Cmd: >setreading MythzDummy HtPmp_tDHWAct 51.6<
2025.10.16 11:45:41 5: Starting notify loop for MythzDummy, 1 event(s), first is HtPmp_tDHWAct: 51.6
2025.10.16 11:45:41 5: End notify loop for MythzDummy
2025.10.16 11:45:41 5: Cmd: >setreading MythzDummy AmbAir_t 13.1<
2025.10.16 11:45:41 5: rg_thz: not on any display, ignoring notify
2025.10.16 11:45:41 5: rg_thz_stat: not on any display, ignoring notify
2025.10.16 11:45:41 5: End notify loop for Mythz
2025.10.16 11:45:41 5: Cmd: >sleep 0.1 quiet<
2025.10.16 11:45:41 3: Mythz.Gets.30s: dhwTemp: 51.6 outsideTemp: 13.1 dhwSetTemp: 10 compBlockTime: 0 out: 0000 heatBlockTime: 0 dhwBoosterStage: 0 pasteurisationMode: 0 dhwOpMode: setback x36: C525
2025.10.16 11:45:41 5: redefine at command Mythz.Gets.30s as +*00:00:30
get Mythz sDHW;
sleep 0.1 quiet;
get Mythz sFan;
sleep 0.1 quiet;
get Mythz sControl
2025.10.16 11:45:41 5: Starting notify loop for Mythz.Gets.30s, 1 event(s), first is Next: 11:46:10
2025.10.16 11:45:41 5: End notify loop for Mythz.Gets.30s
2025.10.16 11:45:41 4: BindingsIo (fhempy_local): >>> WS: {"awaitId": 90727029, "NAME": "tuya_local_bfea531a427393198ebq7p", "msgtype": "command", "command": "readingsBulkUpdateIfChanged($defs{'tuya_local_bfea531a427393198ebq7p'},'dp_21','1');;"}
2025.10.16 11:45:41 5: BindingsIo_storeMessage: {"awaitId": 90727029, "NAME": "tuya_local_bfea531a427393198ebq7p", "msgtype": "command", "command": "readingsBulkUpdateIfChanged($defs{'tuya_local_bfea531a427393198ebq7p'},'dp_21','1');;"}
2025.10.16 11:45:41 5: BindingsIo_checkResponseByAllNames size 1
2025.10.16 11:45:41 4: BindingsIo(fhempy_local): processCommand (90727029): readingsBulkUpdateIfChanged($defs{'tuya_local_bfea531a427393198ebq7p'},'dp_21','1');;
2025.10.16 11:45:41 4: BindingsIo (fhempy_local): <<< WS: {"awaitId":90727029,"result":null,"error":0}
2025.10.16 11:45:41 5: DevIo_SimpleWrite fhempy_local: 7b2261776169744964223a39303732373032392c22726573756c74223a6e756c6c2c226572726f72223a307d
2025.10.16 11:45:41 5: BindingsIo_checkResponseByAllNames size 0
2025.10.16 11:45:41 5: BindingsIo (fhempy_local): Waiting for id 0
2025.10.16 11:45:41 4: BindingsIo (fhempy_local): >>> WS: {"awaitId": 82011281, "NAME": "tuya_local_bfea531a427393198ebq7p", "msgtype": "command", "command": "readingsBulkUpdateIfChanged($defs{'tuya_local_bfea531a427393198ebq7p'},'dp_22','567');;"}
2025.10.16 11:45:41 5: BindingsIo_storeMessage: {"awaitId": 82011281, "NAME": "tuya_local_bfea531a427393198ebq7p", "msgtype": "command", "command": "readingsBulkUpdateIfChanged($defs{'tuya_local_bfea531a427393198ebq7p'},'dp_22','567');;"}
2025.10.16 11:45:41 5: BindingsIo_checkResponseByAllNames size 1
2025.10.16 11:45:41 4: BindingsIo(fhempy_local): processCommand (82011281): readingsBulkUpdateIfChanged($defs{'tuya_local_bfea531a427393198ebq7p'},'dp_22','567');;
2025.10.16 11:45:41 4: BindingsIo (fhempy_local): <<< WS: {"error":0,"result":null,"awaitId":82011281}
2025.10.16 11:45:41 5: DevIo_SimpleWrite fhempy_local: 7b226572726f72223a302c22726573756c74223a6e756c6c2c2261776169744964223a38323031313238317d
2025.10.16 11:45:41 5: BindingsIo_checkResponseByAllNames size 0
2025.10.16 11:45:41 5: BindingsIo (fhempy_local): Waiting for id 0
2025.10.16 11:45:41 4: BindingsIo (fhempy_local): >>> WS: {"awaitId": 43624516, "NAME": "tuya_local_bfea531a427393198ebq7p", "msgtype": "command", "command": "readingsBulkUpdateIfChanged($defs{'tuya_local_bfea531a427393198ebq7p'},'dp_23','29735');;"}
2025.10.16 11:45:41 5: BindingsIo_storeMessage: {"awaitId": 43624516, "NAME": "tuya_local_bfea531a427393198ebq7p", "msgtype": "command", "command": "readingsBulkUpdateIfChanged($defs{'tuya_local_bfea531a427393198ebq7p'},'dp_23','29735');;"}
2025.10.16 11:45:41 5: BindingsIo_checkResponseByAllNames size 1
2025.10.16 11:45:41 4: BindingsIo(fhempy_local): processCommand (43624516): readingsBulkUpdateIfChanged($defs{'tuya_local_bfea531a427393198ebq7p'},'dp_23','29735');;
2025.10.16 11:45:41 4: BindingsIo (fhempy_local): <<< WS: {"result":null,"awaitId":43624516,"error":0}
2025.10.16 11:45:41 5: DevIo_SimpleWrite fhempy_local: 7b22726573756c74223a6e756c6c2c2261776169744964223a34333632343531362c226572726f72223a307d
2025.10.16 11:45:41 5: BindingsIo_checkResponseByAllNames size 0
2025.10.16 11:45:41 5: BindingsIo (fhempy_local): Waiting for id 0
2025.10.16 11:45:41 4: BindingsIo (fhempy_local): >>> WS: {"awaitId": 37057844, "NAME": "tuya_local_bfea531a427393198ebq7p", "msgtype": "command", "command": "readingsBulkUpdateIfChanged($defs{'tuya_local_bfea531a427393198ebq7p'},'dp_24','16145');;"}
2025.10.16 11:45:41 5: BindingsIo_storeMessage: {"awaitId": 37057844, "NAME": "tuya_local_bfea531a427393198ebq7p", "msgtype": "command", "command": "readingsBulkUpdateIfChanged($defs{'tuya_local_bfea531a427393198ebq7p'},'dp_24','16145');;"}
2025.10.16 11:45:41 5: BindingsIo_checkResponseByAllNames size 1
2025.10.16 11:45:41 4: BindingsIo(fhempy_local): processCommand (37057844): readingsBulkUpdateIfChanged($defs{'tuya_local_bfea531a427393198ebq7p'},'dp_24','16145');;
2025.10.16 11:45:41 4: BindingsIo (fhempy_local): <<< WS: {"error":0,"awaitId":37057844,"result":null}
2025.10.16 11:45:41 5: DevIo_SimpleWrite fhempy_local: 7b226572726f72223a302c2261776169744964223a33373035373834342c22726573756c74223a6e756c6c7d
2025.10.16 11:45:41 5: BindingsIo_checkResponseByAllNames size 0
2025.10.16 11:45:41 5: BindingsIo (fhempy_local): Waiting for id 0
2025.10.16 11:45:41 4: BindingsIo (fhempy_local): >>> WS: {"awaitId": 39083664, "NAME": "tuya_local_bfea531a427393198ebq7p", "msgtype": "command", "command": "readingsBulkUpdateIfChanged($defs{'tuya_local_bfea531a427393198ebq7p'},'dp_25','2580');;"}
2025.10.16 11:45:41 5: BindingsIo_storeMessage: {"awaitId": 39083664, "NAME": "tuya_local_bfea531a427393198ebq7p", "msgtype": "command", "command": "readingsBulkUpdateIfChanged($defs{'tuya_local_bfea531a427393198ebq7p'},'dp_25','2580');;"}
2025.10.16 11:45:41 5: BindingsIo_checkResponseByAllNames size 1
2025.10.16 11:45:41 4: BindingsIo(fhempy_local): processCommand (39083664): readingsBulkUpdateIfChanged($defs{'tuya_local_bfea531a427393198ebq7p'},'dp_25','2580');;
2025.10.16 11:45:41 4: BindingsIo (fhempy_local): <<< WS: {"error":0,"result":null,"awaitId":39083664}
2025.10.16 11:45:41 5: DevIo_SimpleWrite fhempy_local: 7b226572726f72223a302c22726573756c74223a6e756c6c2c2261776169744964223a33393038333636347d
2025.10.16 11:45:41 5: BindingsIo_checkResponseByAllNames size 0
2025.10.16 11:45:41 5: BindingsIo (fhempy_local): Waiting for id 0
2025.10.16 11:45:41 4: BindingsIo (fhempy_local): >>> WS: {"awaitId": 18585184, "NAME": "tuya_local_bfea531a427393198ebq7p", "msgtype": "command", "command": "readingsBulkUpdateIfChanged($defs{'tuya_local_bfea531a427393198ebq7p'},'dp_26','0');;"}
2025.10.16 11:45:41 5: BindingsIo_storeMessage: {"awaitId": 18585184, "NAME": "tuya_local_bfea531a427393198ebq7p", "msgtype": "command", "command": "readingsBulkUpdateIfChanged($defs{'tuya_local_bfea531a427393198ebq7p'},'dp_26','0');;"}
2025.10.16 11:45:41 5: BindingsIo_checkResponseByAllNames size 1
2025.10.16 11:45:41 4: BindingsIo(fhempy_local): processCommand (18585184): readingsBulkUpdateIfChanged($defs{'tuya_local_bfea531a427393198ebq7p'},'dp_26','0');;
2025.10.16 11:45:41 4: BindingsIo (fhempy_local): <<< WS: {"error":0,"result":null,"awaitId":18585184}
2025.10.16 11:45:41 5: DevIo_SimpleWrite fhempy_local: 7b226572726f72223a302c22726573756c74223a6e756c6c2c2261776169744964223a31383538353138347d
2025.10.16 11:45:41 5: BindingsIo_checkResponseByAllNames size 0
2025.10.16 11:45:41 5: BindingsIo (fhempy_local): Waiting for id 0
2025.10.16 11:45:41 5: GET /fhem?XHR=1&inform=type%3Dstatus%3Bfilter%3Droom%3DStrom%3Bsince%3D1760607932.9526498%3Bfmt%3DJSON&fw_id=1760606289.98467&timestamp=1760607939626 HTTP/1.1
Host: <entfernt>:8084
Accept: */*
Sec-Fetch-Site: same-origin
Sec-Fetch-Mode: cors
User-Agent: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/18.7 Mobile/15E148 Safari/604.1
Referer: https://<entfernt>:8084/fhem?room=Strom
Sec-Fetch-Dest: empty
Authorization: Basic <entfernt>
Accept-Language: de-DE,de;q=0.9
Priority: u=3, i
Accept-Encoding: gzip, deflate, br
Cookie: dashboard_activetab=2
Connection: keep-alive
2025.10.16 11:45:41 4: WEBphone_::ffff:194.39.218.13_54678 GET /fhem?XHR=1&inform=type%3Dstatus%3Bfilter%3Droom%3DStrom%3Bsince%3D1760607932.9526498%3Bfmt%3DJSON&fw_id=1760606289.98467&timestamp=1760607939626; BUFLEN:0
Killed

rudolfkoenig · 17 Oktober 2025, 08:45:06

ZitatKilled

Das war kein "Absturz", der Prozess wurde (von aussen) terminiert.

Eine moegliche Ursache ist Speicherleck.
Wenn ein Prozess zu gross wird, dann wird es vom Kernel terminiert, das wird dann auch im Kernel-Log als solches dokumentiert.

TheTrumpeter · 17 Oktober 2025, 09:42:45

Sudo dmesg -f kern -T zeigt im relevanten Zeitbereich nichts an.

rudolfkoenig · 17 Oktober 2025, 09:55:50

Kannst Du bitte trotzdem beobachten, wie gross der Speicherbedarf bzw. -wachstum von FHEM ist?

Wenn das nicht der Kernel war, dann jemand anderes.

Der Text "Killed" kommt nicht von FHEM, sondern von Shell (im Terminal), wo FHEM gestartet wurde, und zeigt, das der gestartete Pozess mit Signal 9 (SIGKILL) beendet wurde.

Soweit ich sehe, gibt es ein paar Module (DbLog, CoProcess, SubProcess), die SIGKILL versenden, allerdings nur an Unterprozesse.
Das versehentlich der Hauptprozess dabei getroffen wird, ist unwahrscheinlich.

passibe · 17 Oktober 2025, 11:31:31

Hm naja, extern gekillt oder nicht – es tritt ja schon immer nach Aufruf dieser URL auf, oder?

Zitat von: TheTrumpeter am 17 Oktober 2025, 07:04:362025.10.16 09:15:28 5: GET /fhem?XHR=1&inform=type%3Dstatus%3Bfilter%3Droom%3DStrom%3Bsince%3D1760598915.8880098%3Bfmt%3DJSON&fw_id=1760587126.90304&timestamp=1760598924249 HTTP/1.1
Host: <entfernt>:8084
Accept: */*
Sec-Fetch-Site: same-origin
Sec-Fetch-Mode: cors
User-Agent: Mozilla/5.0 (iPhone; CPU iPhone OS 18_7_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/18.7 Mobile/15E148 Safari/604.1
Referer: https://<entfernt>:8084/fhem?room=Strom
Sec-Fetch-Dest: empty
Authorization: Basic <entfernt>
Accept-Language: de-DE,de;q=0.9
Priority: u=3, i
Accept-Encoding: gzip, deflate, br
Cookie: dashboard_activetab=2
Connection: keep-alive
2025.10.16 09:15:28 4: WEBphone_::ffff:194.39.218.13_60651 GET /fhem?XHR=1&inform=type%3Dstatus%3Bfilter%3Droom%3DStrom%3Bsince%3D1760598915.8880098%3Bfmt%3DJSON&fw_id=1760587126.90304&timestamp=1760598924249; BUFLEN:0

Woher genau kommt dieser Aufruf und was wird damit abgerufen? Bin nicht so tief im FHEMWEB-Game drin, ist das irgendeine automatische Aktualisierung im Hintergrund (JavaScript?) oder erfolgt so ein Request erst, wenn man manuell auf den jeweiligen Raum (hier "Strom") klickt?

Vielleicht auch mal den Raum "Strom" checken, ob da irgendwas auffälliges drin ist? Eventuell auch mal Devices einzeln raus-verschieben, um ggfs. die Fehlerquelle zu isolieren?

Vielleicht kann man die URL ja auch mal mit curl aufrufen und schauen, ob man so einen Absturz provozieren kann.

TheTrumpeter · 17 Oktober 2025, 12:00:13

Zitat von: rudolfkoenig am 17 Oktober 2025, 09:55:50Kannst Du bitte trotzdem beobachten, wie gross der Speicherbedarf bzw. -wachstum von FHEM ist?

Speicherverlauf von gestern gebe ich in den Anhang.

Ich nutze fhempy, das definitiv ein "Speicherleck" hat. Daher starte ich fhempy ab einer bestimmten Speicherschwelle neu, was aber seit dem Wechsel auf den RasPi-4B mit 4 GB nicht mehr erforderlich war. Für mich schaut der Speicherverlauf jedenfalls unkritisch aus, insbesondere nach dem ersten Absturz (weil dadurch auch fhempy neu gestartet wurde).

Zitat von: rudolfkoenig am 17 Oktober 2025, 09:55:50Der Text "Killed" kommt nicht von FHEM, sondern von Shell (im Terminal), wo FHEM gestartet wurde, und zeigt, das der gestartete Pozess mit Signal 9 (SIGKILL) beendet wurde.

Hm...
Ich habe tatsächlich vor langer Zeit einen Watchdog auf Systemebene eingerichtet, der auf die Aktualisierung einer bestimmten Datei im RAM-Drive prüft, um ein "eingefrorenes FHEM" erkennen zu können. Dieser killt den FHEM-Prozess dann nach ein paar Minuten und startet ihn neu. Der Neustart funktioniert derzeit natürlich nicht, weil FHEM mit der Debug-Ausgabe von weiter oben manuell gestartet wurde.
Es kommen dann auch im Minutentakt eMails, die das Problem anzeigen, d.h. ich glaube 2x "hängt" und 1x "Neustart versucht".
In seltenen Fällen hat sich das System nach 1 oder 2 eMails wieder "erfangen", d.h. FHEM hat wohl 1-2 Minuten die Datei nicht aktualisiert, dann aber doch "weitergemacht".

Müsste später nachschauen wie lange es dauert, bis "gekillt" wird, aber ich meine mindestens 3 Minuten.

D.h. das erklärt dann das "killed" in der Ausgabe. Warum sich davor (mindestens) 3 Minuten nichts mehr tut bleibt weiterhin offen.

TheTrumpeter · 17 Oktober 2025, 12:05:58

Zitat von: passibe am 17 Oktober 2025, 11:31:31Woher genau kommt dieser Aufruf und was wird damit abgerufen? Bin nicht so tief im FHEMWEB-Game drin, ist das irgendeine automatische Aktualisierung im Hintergrund (JavaScript?) oder erfolgt so ein Request erst, wenn man manuell auf den jeweiligen Raum (hier "Strom") klickt?

Das kann ich auch nicht sagen, aber ich glaube, dass es gestern immer ein "manuelles Aktualisieren" über den Browser war. Typischerweise habe ich dem Raum "Strom" geöffnet, wenn ich den Browser aufrufe aktualisiere ich dann das Tab.

Zitat von: passibe am 17 Oktober 2025, 11:31:31Vielleicht auch mal den Raum "Strom" checken, ob da irgendwas auffälliges drin ist? Eventuell auch mal Devices einzeln raus-verschieben, um ggfs. die Fehlerquelle zu isolieren?

Ich glaube, dass es Zufall war, weil das der typischweise geöffnete Raum ist.
Abgesehen von "SolarForecast", das tatsächlich eine sich laufend aktualisierende Grafik anzeigt, sind da einfach viele Devices gelistet (Steckdosen zum ein/ausschalten), von denen 2 zusätzlich mittels "StateFormat" dynamisch Werte geändert werden.