FHEM friert alle paar Tage ein

[audimax]

Hallo zusammen,

mein FHEM läuft jetzt seit etwa 4 Jahren und die letzten zwei davon als LXC (Ubuntu) auf einem PROXMOX Server.
Seit ein paar Wochen gibt es leider immer wieder das Problem, dass FHEM plötzlich nicht mehr reagiert.
Der Prozess läuft zwar dann noch, aber ist über WEB nicht erreichbar. Über telnet kann ich zwar eine Verbindung aufbauen, aber der Prozess reagiert hier auch auf nichts. Es hilft nur ein Neustart von FHEM.

Habe jetzt mal den globalen log auf verbose 4 gestellt, aber da gibt es leider auch nichts hilfreiches:

Code Auswählen Erweitern

23.02.24 08:39:40 4: ModBusLine: checkDelays found commDelay not over, set timer to try again in 0.099
2023.02.24 08:39:40 4: ModBusLine: ProcessRequestQueue (V4.4.14 - 30.1.2023) qlen 3, sending 0703021c00014412 via 192.168.42.44:2001, read buffer empty,
request: id 7, read fc 3 h00540, len 1, master device KWL, reading FreeHeatingTemp (getUpdate for FreeHeatingTemp len 1), queued 1.89 secs ago
2023.02.24 08:39:40 4: ModBusLine: ParseFrameStart (RTU, master) extracted id 7, fCode 3 and potential data 0200d2
2023.02.24 08:39:40 4: KWL: CreateDataObjects assigns value 21.0 B0C to FreeHeatingTemp
2023.02.24 08:39:40 4: ModBusLine: HandleResponse done, current frame / read buffer: 07030200d2b019, id 7, fCode 3,
request: id 7, read fc 3 h00540, len 1, master device KWL, reading FreeHeatingTemp (getUpdate for FreeHeatingTemp len 1), queued 1.92 secs ago, sent 0.03 secs ago,
response: id 7, fc 3, h00540, len 1, values 00d2
2023.02.24 08:39:40 4: ModBusLine: checkDelays found commDelay not over, set timer to try again in 0.099
2023.02.24 08:39:40 4: ModBusLine: ProcessRequestQueue (V4.4.14 - 30.1.2023) qlen 2, sending 0703030000018428 via 192.168.42.44:2001, read buffer empty,
request: id 7, read fc 3 h00768, len 1, master device KWL, reading Power (getUpdate for Power len 1), queued 2.03 secs ago
2023.02.24 08:39:40 4: ModBusLine: ParseFrameStart (RTU, master) extracted id 7, fCode 3 and potential data 020001
2023.02.24 08:39:40 4: KWL: CreateDataObjects assigns value on to Power
2023.02.24 08:39:40 4: ModBusLine: HandleResponse done, current frame / read buffer: 0703020001f184, id 7, fCode 3,
request: id 7, read fc 3 h00768, len 1, master device KWL, reading Power (getUpdate for Power len 1), queued 2.06 secs ago, sent 0.03 secs ago,
response: id 7, fc 3, h00768, len 1, values 0001
2023.02.24 08:39:40 4: ModBusLine: checkDelays found commDelay not over, set timer to try again in 0.099
2023.02.24 08:39:40 4: ModBusLine: ProcessRequestQueue (V4.4.14 - 30.1.2023) qlen 1, sending 07030307000135e9 via 192.168.42.44:2001, read buffer empty,
request: id 7, read fc 3 h00775, len 1, master device KWL, reading Mode (getUpdate for Mode len 1), queued 2.16 secs ago
2023.02.24 08:39:40 4: ModBusLine: ParseFrameStart (RTU, master) extracted id 7, fCode 3 and potential data 020003
2023.02.24 08:39:40 4: KWL: CreateDataObjects assigns value Manual to Mode
2023.02.24 08:39:40 4: ModBusLine: HandleResponse done, current frame / read buffer: 07030200037045, id 7, fCode 3,
request: id 7, read fc 3 h00775, len 1, master device KWL, reading Mode (getUpdate for Mode len 1), queued 2.19 secs ago, sent 0.03 secs ago,
response: id 7, fc 3, h00775, len 1, values 0003
2023.02.24 08:39:41 4: KodiBox: KODI_Check
2023.02.24 08:39:41 4: KodiBox: KODI_CheckConnection: Connection still alive. Last data from Kodi received 59.9970939159393 s ago
2023.02.24 08:39:41 4: KodiBox: KODI_Update
2023.02.24 08:39:41 4: KodiBox: KODI_PlayerUpdate
2023.02.24 08:39:41 4: KodiBox: KODI_UpdatePlayerItem
2023.02.24 08:39:41 4: KodiBox: KODI_UpdatePlayerItem - cancelled (disconnected or not playing)
2023.02.24 08:39:41 4: KodiBox: KODI_ProcessRead
2023.02.24 08:39:41 4: KodiBox: KODI_ProcessRead: Decoding JSON message. Length: 160 Content: {"id":6727,"jsonrpc":"2.0","result":{"muted":false,"name":"Kodi","version":{"major":18,"minor":9,"revision":"
2023.02.24 08:39:41 4: KodiBox: KODI_ProcessResponse: updating readings
2023.02.24 08:39:41 4: KodiBox: KODI_ProcessRead
2023.02.24 08:39:41 4: KodiBox: KODI_ProcessRead: Decoding JSON message. Length: 159 Content: {"id":6728,"jsonrpc":"2.0","result":{"fullscreen":false,"skin":{"id":"skin.estuary","name":"Estuary"},"stereo
2023.02.24 08:39:41 4: KodiBox: KODI_ProcessResponse: updating readings
2023.02.24 08:39:41 4: KodiBox: KODI_ProcessRead
2023.02.24 08:39:41 4: KodiBox: KODI_ProcessRead: Decoding JSON message. Length: 41 Content: {"id":"6729","jsonrpc":"2.0","result":[]}
2023.02.24 08:39:44 4: BlockingCall (PRESENCE_DoLocalPingScan): created child (16888), uses telnetPort to connect back
2023.02.24 08:39:44 4: Connection accepted from telnetPort_127.0.0.1_56954
2023.02.24 08:39:47 4: PRESENCE (HandyMax) - rescheduling next check in 30 seconds
2023.02.24 08:39:48 4: IP: 192.168.42.88 -> 192.168.42.88
2023.02.24 08:39:48 4: http://192.168.42.88/status: HTTP response code 200
2023.02.24 08:39:48 4: TE_ROLLO_states exec {rollo_states()}
2023.02.24 08:39:48 4: dummy set EG_ROLLO_status 0
2023.02.24 08:39:48 4: dummy set OG_ROLLO_status 0
2023.02.24 08:39:48 4: dummy set DG_ROLLO_status 0
2023.02.24 08:39:48 4: AutoShuttersControl (myASC) - Devname: OG_TOBI_rollo_w Name: myASC Notify: $VAR1 = [
          'inttemp: 43.67'
        ];

2023.02.24 08:42:07 1: Including fhem.cfg
2023.02.24 08:42:07 3: WEB: port 8083 opened

Hat dazu jemand eine Idee?

Was kann ich an Infos liefern?

Freezemon ist an, hat aber für heute kein Logfile geschrieben.

Der automatische Neustart erfolgt mit systemd_watchdog ist aber natürlich auch keine echte Lösung.

In den letzten Wochen gab es zwar etwas neues (eine PV), die wird über httpmod abgefragt und einen arducounter über ser2net. Kann hier die Ursache liegen?
Raus nehmen möchte ich die nicht, weil sonst ja die Daten Weg sind.

Verbose 5 hat unglaublich riesige Files erzeugt, wäre aber dann vermutlich der nächste Schritt. Es dauert aber leider dann eben 3-5 Tage bis sich was tut.

Bin für Tipps sehr dankbar!
Viele Grüße
Max

[Wernieman]

FHEM läuft, reagiert aber nicht, hört sich immer nach Freeze an, es sei denn, zu der Zeit läuft FHEM mit 100% CPU.

Hast Du zu der Problemzeit eventuell Internetprobleme?

[rudolfkoenig]

Verbose 5 hat unglaublich riesige Files erzeugt, wäre aber dann vermutlich der nächste Schritt. Es dauert aber leider dann eben 3-5 Tage bis sich was tut.

kill -USR1 <fhempid> schaltet verbose auf 5, wenn FHEM halbwegs aktiv ist, sprich die globale select-Schleife abarbeiten kann.

Hast Du zu der Problemzeit eventuell Internetprobleme?

... und ist "attr global dnsServer" gesetzt?

[audimax]

Erstmal vielen Dank für die Antworten.

kill -USR1 <fhempid> schaltet verbose auf 5, wenn FHEM halbwegs aktiv ist, sprich die globale select-Schleife abarbeiten kann.
... und ist "attr global dnsServer" gesetzt?

Ok, super dann werde ich das beim nächsten mal probieren, falls ich verbose 5 nicht dauerhaft durchhalte.
Im Moment habe ich verbose mal auf 5 gesetzt und hoffe, dass ich dann im Fall der Fälle auch noch was sehe vor lauter Meldungen

global dnsServer war und ist gesetzt (ist ein pihole auf einem anderen LXC)

FHEM läuft, reagiert aber nicht, hört sich immer nach Freeze an, es sei denn, zu der Zeit läuft FHEM mit 100% CPU.

Hast Du zu der Problemzeit eventuell Internetprobleme?

Im Problemfall ist die CPU Last quasi 0. In top ist der FHEM Prozess unauffällig (eher zu wenig Last)

Internetprobleme schließe ich eher aus. Beim ersten mal habe ich FHEM per VPN von außen neu gestartet.
Ob es natürlich genau im Moment des Ausfalls Probleme gibt, die danach wieder weg sind ... Die Fritzbox sagt zumindest nein.

Danke schonmal für alle weiteren Vorschläge und Tipps.

[rudolfkoenig]

Im Problemfall ist die CPU Last quasi 0. In top ist der FHEM Prozess unauffällig (eher zu wenig Last)

Wenn aus dem FHEM-Log nichts klar wird, dann kann man auch mit "strace -p <fhempid>" versuchen.

[audimax]

Hallo nochmal,

hatte jetzt wieder zwei Crashes und mit verbose 5 tatsächlich auch was im log stehen:

Code Auswählen Erweitern

2023.02.28 04:03:33 5: KWL: ParseDataString called from HandleResponse with data hex 0000, type h, adr 00515, op read
2023.02.28 04:03:33 5: KWL: SplitDataString called from ParseDataString with data hex 0000, type h, adr 00515, valuesLen 1, op read
2023.02.28 04:03:33 5: KWL: CreateDataObjects called from ParseDataString with objList h00515
2023.02.28 04:03:33 5: KWL: CreateDataObjects sortedList h00515
2023.02.28 04:03:33 5: KWL: CreateParseInfoCache called
2023.02.28 04:03:33 5: KWL: CreateDataObjects unpacked 0000 with n to 0
2023.02.28 04:03:33 4: KWL: CreateDataObjects assigns value 0 to T3offset
2023.02.28 04:03:33 5: KWL: ParseDataString created 1 readings
2023.02.28 04:03:33 4: ModBusLine: HandleResponse done, current frame / read buffer: 07030200003044, id 7, fCode 3,
request: id 7, read fc 3 h00515, len 1, master device KWL, reading T3offset (getUpdate for T3offset len 1), queued 1.38 secs ago, sent 0.03 secs ago,
response: id 7, fc 3, h00515, len 1, values 0000
2023.02.28 04:03:33 5: ModBusLine: ResetExpect for HandleResponse from response to idle
2023.02.28 04:03:33 5: ModBusLine: StartQueueTimer called from HandleResponse sets internal timer to process queue in 0.000 seconds
2023.02.28 04:03:33 5: ModBusLine: DropFrame called from ReadFn - drop 07030200003044
2023.02.28 04:03:33 5: ModBusLine: ProcessRequestQueue called from Fhem internal timer as queue:ModBusLine, qlen 6, request: request: id 7, read fc 3 h00516, len 1, master device KWL, reading T4offset (getUpdate for T4offset len 1), queued 1.38 secs ago
2023.02.28 04:03:33 5: ModBusLine: checkDelays commDelay, last communication with same device was 0.002 secs ago, required delay is 0.1
2023.02.28 04:03:33 5: ModBusLine: checkDelays sendDelay, last send to same device was 0.033 secs ago, required delay is 0.1
2023.02.28 04:03:33 5: ModBusLine: checkDelays clientSwitchDelay is not relevant
2023.02.28 04:03:33 5: ModBusLine: checkDelays busDelayRead, last activity on bus was 0.002 secs ago, required delay is 0
2023.02.28 04:03:33 4: ModBusLine: checkDelays found commDelay not over, set timer to try again in 0.098
2023.02.28 04:03:33 5: IOduino FRM:>f0730102f7
2023.02.28 04:03:33 5: DevIo_SimpleWrite IOduino_192.168.42.42_49155: f0730102f7
2023.02.28 04:06:24 5: Initializing Type Library:
2023.02.28 04:06:24 1: Including fhem.cfg

Code Auswählen Erweitern

2023.03.03 18:37:47 4: ModBusLine: HandleResponse done, current frame / read buffer: 07030200b031f0, id 7, fCode 3,
request: id 7, read fc 3 h00257, len 1, master device KWL, reading T2_Zuluft (getUpdate for T2_Zuluft len 1), queued 0.17 secs ago, sent 0.03 secs ago,
response: id 7, fc 3, h00257, len 1, values 00b0
2023.03.03 18:37:47 5: ModBusLine: ResetExpect for HandleResponse from response to idle
2023.03.03 18:37:47 5: ModBusLine: StartQueueTimer called from HandleResponse sets internal timer to process queue in 0.000 seconds
2023.03.03 18:37:47 5: ModBusLine: DropFrame called from ReadFn - drop 07030200b031f0
2023.03.03 18:37:47 5: ModBusLine: ProcessRequestQueue called from Fhem internal timer as queue:ModBusLine, qlen 15, request: request: id 7, read fc 3 h00258, len 1, master device KWL, reading T3_Abluft (getUpdate for T3_Abluft len 1), queued 0.17 secs ago
2023.03.03 18:37:47 5: ModBusLine: checkDelays clientSwitchDelay is not relevant
2023.03.03 18:37:47 5: ModBusLine: checkDelays busDelayRead, last activity on bus was 0.002 secs ago, required delay is 0
2023.03.03 18:37:47 5: ModBusLine: checkDelays commDelay, last communication with same device was 0.002 secs ago, required delay is 0.1
2023.03.03 18:37:47 5: ModBusLine: checkDelays sendDelay, last send to same device was 0.033 secs ago, required delay is 0.1
2023.03.03 18:37:47 4: ModBusLine: checkDelays found commDelay not over, set timer to try again in 0.098
2023.03.03 18:37:48 5: ModBusLine: ProcessRequestQueue called from Fhem internal timer as queue:ModBusLine, qlen 15, request: request: id 7, read fc 3 h00258, len 1, master device KWL, reading T3_Abluft (getUpdate for T3_Abluft len 1), queued 0.27 secs ago
2023.03.03 18:37:48 5: ModBusLine: checkDelays clientSwitchDelay is not relevant
2023.03.03 18:37:48 5: ModBusLine: checkDelays commDelay, last communication with same device was 0.101 secs ago, required delay is 0.1
2023.03.03 18:37:48 5: ModBusLine: checkDelays sendDelay, last send to same device was 0.132 secs ago, required delay is 0.1
2023.03.03 18:37:48 5: ModBusLine: checkDelays busDelayRead, last activity on bus was 0.101 secs ago, required delay is 0
2023.03.03 18:37:48 4: ModBusLine: ProcessRequestQueue (V4.4.14 - 30.1.2023) qlen 15, sending 0703010200012450 via 192.168.42.44:2001, read buffer empty,
request: id 7, read fc 3 h00258, len 1, master device KWL, reading T3_Abluft (getUpdate for T3_Abluft len 1), queued 0.27 secs ago
2023.03.03 18:37:48 5: ModBusLine: Send called from ProcessRequestQueue
2023.03.03 18:37:48 5: DevIo_SimpleWrite ModBusLine: 0703010200012450
2023.03.03 18:37:48 5: ModBusLine: StartQueueTimer called from ProcessRequestQueue sets internal timer to process queue in 1.000 seconds
2023.03.03 18:37:48 5: IOduino FRM:>f0730102f7
2023.03.03 18:37:48 5: DevIo_SimpleWrite IOduino_192.168.42.42_49153: f0730102f7
2023.03.03 18:40:15 5: Initializing Type Library:
2023.03.03 18:40:15 1: Including fhem.cfg

Bei der Interpretation bin ich mir allerdings nicht so ganz sicher.
IOduino ist einer von drei Arduino Nano mit Firmata, über diesen sind i2c und 1-wire Sensoren angeschlossen.

List:

Code Auswählen Erweitern

Internals:
   CONNECTS   1
   DEF        3031 global
   DRIVER_VERSION 0.69
   DeviceName 3031
   FD         51
   FUUID      61d9fc7d-f33f-0af0-adde-d15171aee791351b
   LAST_RECEIVED 2023-03-03 19:13:25
   NAME       IOduino
   NOTIFYDEV  global
   NR         475
   NTFY_ORDER 50-IOduino
   PORT       3031
   STATE      Initialized
   TYPE       FRM
   eventCount 13
   firmware   IOduino.ino
   firmware_version V_2_10
   i2c_pins   18,19
   onewire_pins 2,3,5,6,7,8,9,14,15,16,17,18,19
   protocol_version V_2_06
   READINGS:
     2023-03-03 19:15:29   error           I2C: Too few bytes received
     2023-03-03 19:13:33   state           Initialized
   SERIAL:
   SocketDevice:
     BUF       
     DeviceName 3031
     FD         15
     LAST_RECEIVED 2023-03-03 20:15:53
     NAME       IOduino_192.168.42.42_49153
     NR         718
     PEER       192.168.42.42
     PORT       49153
     SNAME      IOduino
     SSL       
     STATE      Connected
     TEMPORARY  1
     TYPE       FRM
     READINGS:
       2023-03-03 19:13:25   state           Connected
Attributes:
   i2c-config 5000
   ping-interval 10000

Da es beide Male als letztes im Log stand würde ich davon ausgehen, dass es mit diesem Firmata Arduino zu tun hat. Nach dem Neustart kommen die anderen beiden Arduino von selbst zurück. Der IOduino kommt erst nach einem Reset des Arduino wieder zurück.

Falls es wirklich an diesem Arduino liegt muss ich dazu sagen, dass dieser schon über ein Jahr läuft. Angefangen hat es aber erst vor ein paar Wochen. Ist die Hardware im Eimer? Evtl. die Arduino Netzwerkkarte?

Als nächstes würde ich mal porbieren diesen Arduino mal für eine Woche vom Netz zu nehmen und zu schauen was passiert.
Hat jemand sonst einen Vorschlag?

Andere Frage: Wie kann es sein, dass sich FHEM so verrennt und deswegen nicht mehr reagiert? Ist hier irgendwo ein BUG bei dem ich helfen kann?

Gibt es eine Hardwareempfehlung um 1-Wire und I2C per Netzwerk an FHEM anzubinden? (wegen Proxmox will ich kein USB)

Danke und viele Grüße
Max

[rudolfkoenig]

Bei einem Crash wuerde ich FHEM im Terminal (besser screen oder vgl.) starten, es gibt bestimmte Faelle, wo die (automatische) Umleitung von STDOUT und STDERR ins FHEM-Log nicht reicht.