[GELÖST] ERROR: Unexpected FHEM termination, waiting to reappear

[Tabadorer]

Moin,

fhem läuft in Docker seit Monaten stabil. Jetzt habe ich meinen gesamten Server neu gestartet und nun startet der fhem Container nicht mehr durch. Die anderen Container haben keine Probleme.

Code Auswählen Erweitern

ERROR: Unexpected FHEM termination, waiting to reappear

hier mal das Log, was ich beim Start beobachten kann

Code Auswählen Erweitern

2025.02.17 07:55:54.617 3: Opening ModBusSunnyIsland device 3:502
2025.02.17 07:55:54.619 3: Opening Mosquitto device 192.168.1.235:1883
2025.02.17 07:55:54.695 3: Mosquitto device opened
2025.02.17 07:55:54.698 3: Opening Mosquitto_public device broker.emqx.io:8883
2025.02.17 07:55:58.758 3: Mosquitto_public device opened
2025.02.17 07:55:58.765 3: Opening SMASB device 192.168.0.253:502
2025.02.17 07:55:58.804 2: alexa: alexa-fhem not installed. install with 'sudo npm install -g alexa-fhem'.
2025.02.17 07:55:58.811 1: PERL WARNING: Argument "" isn't numeric in subtraction (-) at (eval 473) line 1.
2025.02.17 07:55:58.811 3: di_Awtrix_PVStatus: warning in DOIF_Readings: _diff
2025.02.17 07:56:05.938 1: PERL WARNING: Use of uninitialized value in string eq at FHEM/Meta.pm line 2123.
2025.02.17 07:56:05.939 1: PERL WARNING: Use of uninitialized value in string eq at FHEM/Meta.pm line 2401.
2025.02.17 07:56:05.939 1: PERL WARNING: Use of uninitialized value in string ne at FHEM/Meta.pm line 2404.
sh: 1: echo: echo: I/O error
2025.02.17 07:56:14.915 3: harmony: starting discovery
2025.02.17 07:56:14.917 3: harmony: sending discovery
2025.02.17 07:56:14.994 2: Keine verfügbaren ROOMMATE/GUEST/PET im RESIDENTS Gerät rgr_Bewohner
2025.02.17 07:56:15.097 0: Featurelevel: 6.3
2025.02.17 07:56:15.098 0: Server started with 383 defined entities (fhem.pl:29402/2024-12-05 perl:5.036003 os:linux user:fhem pid:6063)
INFO: FHEM successfully started
2025.02.17 07:56:16.102 3: MQTT2_DEVICE set MQTT2_SchuppenTuerSpot off
2025.02.17 07:56:16.436 0: HourCounter gaszaehler Run.598 first run done countsOverall:992040
decode_string: insufficient data at /usr/src/app/core/lib/perl5/Net/MQTT/Message/Connect.pm line 86.
ERROR: Unexpected FHEM termination, waiting to reappear
/entry.sh: line 850: kill: (6063) - No such process
/entry.sh: line 850: kill: (6063) - No such process
/entry.sh: line 850: kill: (6063) - No such process
/entry.sh: line 850: kill: (6063) - No such process
/entry.sh: line 850: kill: (6063) - No such process
/entry.sh: line 850: kill: (6063) - No such process
/entry.sh: line 850: kill: (6063) - No such process
/entry.sh: line 850: kill: (6063) - No such process
/entry.sh: line 850: kill: (6063) - No such process
/entry.sh: line 850: kill: (6063) - No such process
/entry.sh: line 850: kill: (6063) - No such process
/entry.sh: line 850: kill: (6063) - No such process
/entry.sh: line 850: kill: (6063) - No such process
/entry.sh: line 850: kill: (6063) - No such process
/entry.sh: line 850: kill: (6063) - No such process
/entry.sh: line 850: kill: (6063) - No such process
ERROR: FHEM did NOT reappear, Restarting FHEM
INFO: Starting FHEM
2025.02.17 07:56:33.344 3: From the FHEM_GLOBALATTR environment: attr global logfile log/fhem-%Y-%m-%d.log
2025.02.17 07:56:33.346 3: From the FHEM_GLOBALATTR environment: attr global pidfilename log/fhem.pid
2025.02.17 07:56:33.346 3: From the FHEM_GLOBALATTR environment: attr global nofork 0
2025.02.17 07:56:33.347 3: From the FHEM_GLOBALATTR environment: attr global updateInBackground 1
2025.02.17 07:56:33.352 1: Including fhem.cfg

Ich sehe das in irgendetwas bei MQTT stört. Da aber der Großteil auf MQTT augelegt ist, will ich nicht alle MQTT2_DEVICES deaktivieren oder jedes Gerät auf Verbose 5 setzen. Kann ich bei Docker global die verbosity auf debug ändern?

wenn ich die fhem.cfg durch die Democonfig Austausche, kann ich zumindest die Oberfläche wieder aufrufen. Aber dann habe ich meine Geräte nicht mehr definiert. Also Entweder ist der Fehler direkt in der Configdatei oder in einem der Module die durch definierte Geräte verwendet werden.

Hier noch mein Auszug aus docker-compose.yml

Code Auswählen Erweitern

services:
    fhem:
        restart: always
        container_name: "fhem"
        ports:
            - "8083:8083"
            - "8084:8084"
            - "8089:8089"
        image: fhem/fhem:latest
        volumes:
            - ./fhem/core/:/opt/fhem/
        networks:
            - fhem-network
        environment:
            FHEM_UID: 1000
            FHEM_GID: 1000
            TIMEOUT: 30
            TIMEOUT_STARTING: 180
            RESTART: 1
            TELNETPORT: 7072
            TZ: Europe/Berlin
        devices:
             - "/dev/serial/by-id/usb-FTDI_FT232R_USB_UART_A50285BI-if00-port0:/dev/ttyUSB0"
             - "/dev/serial/by-id/usb-busware.de_CUL868-if00:/dev/ttyUSB1"
        dns:
            - 192.168.1.235
            - 192.168.0.3
            - 8.8.8.8


[JoWiemann]

Hallo,

kannst Du vor dem Starten des Containers die fhem.cfg editieren und dort das global Attribut stacktrace setzen und verbose auf 5 setzen. Dann würde man mehr sehen im Log.

Grüße Jörg

[Otto123]

Das Problem liegt hier

decode_string: insufficient data at /usr/src/app/core/lib/perl5/Net/MQTT/Message/Connect.pm line 86.

Vermutung: dieses Modul bekommt in dem Moment einen nicht erwarteten String geliefert und stürzt ab, weil dieser Fall nicht abgefangen wurde.
Was mich wundert: MQTT2_xxx verwendet mW keine externen Libraries. Verwendest Du andere mqtt Definitionen, also nicht MQTT2_xxx?

[Tabadorer]

kannst Du vor dem Starten des Containers die fhem.cfg editieren und dort das global Attribut stacktrace setzen und verbose auf 5 setzen.

Ja das habe ich gesucht. Ich kann mich nun durch die 40.000 Zeilen wühlen, die in 2 Minuten entstanden sind  . Ich melde mich wenn ich daraus Erkenntnisse gewinnen konnte oder dadurch noch mehr fragen habe.

Was mich wundert: MQTT2_xxx verwendet mW keine externen Libraries. Verwendest Du andere mqtt Definitionen, also nicht MQTT2_xxx?

Nein das ist Standard. Wenn ich per MQTT ein Gerät steuere, dann immer mit MQTT2_Device. Und ich nutze immer MQTT, sofern das Endgerät das zulässt.
Aber im nun debuglog konnte ich die Zeile wieder finden, aber davor und danach steht nichts mit Bezug auf MQTT. Es sei denn eine Aktion wird gefeuert und dann vergeht soviel zeit, das sich andere Events dazwischen drängeln

Code Auswählen Erweitern

2025.02.17 17:36:08.494 5: MQTT Mosquitto message sent: Subscribe/at-least-once 9 nodeRed/isCarPresent/at-most-once
2025.02.17 17:36:08.494 5: DevIo_SimpleWrite Mosquitto: 8219000900146e6f64655265642f697343617250726573656e7400
2025.02.17 17:36:08.497 5: MQTT Mosquitto message received: PingResp/at-most-once
2025.02.17 17:36:08.498 5: Starting notify loop for Mosquitto, 1 event(s), first is connection: active
2025.02.17 17:36:08.498 4: DBLogging - check Device: Mosquitto , Event: connection: active
2025.02.17 17:36:08.499 5: End notify loop for Mosquitto
2025.02.17 17:36:08.500 3: SMASB device opened
2025.02.17 17:36:08.500 5: Starting notify loop for SMASB, 1 event(s), first is CONNECTED
2025.02.17 17:36:08.500 4: DBLogging - check Device: SMASB , Event: CONNECTED
2025.02.17 17:36:08.502 5: End notify loop for SMASB
2025.02.17 17:36:08.502 4: SMASB: UpdateTimer called from OpenCB with cmd start sets timer to call update function in 1.8 sec at 17:36:10.349, interval 2
decode_string: insufficient data at /usr/src/app/core/lib/perl5/Net/MQTT/Message/Connect.pm line 86.
2025.02.17 17:36:08.532 5: PRESENCE (goe_http_presence) - starting ping scan: goe_http_presence|192.168.0.212|0|1
2025.02.17 17:36:08.534 5: PRESENCE (presenceKatja) - execute perl function: presenceKatja|{checkAllFritzMACpresent("80:19:70:DA:44:82")}|0
2025.02.17 17:36:08.535 5: Cmd: >{checkAllFritzMACpresent("80:19:70:DA:44:82")}<
2025.02.17 17:36:08.541 5: PRESENCE (presenceKatja) - function returned with: 0


[passibe]

Kannst du vielleicht mal mit einem Tool wie MQTT Explorer mitlesen, was genau da übermittelt wird, wenn FHEM abstürzt?

Ansonsten bietet es sich vielleicht ja auch an, erstmal mit einer "leeren" (also Minimalkonfiguration) fhem.cfg zu starten und erst nach und nach alles hinzuzufügen? Ggfs. auch mit abgeschaltetem autocreate von MQTT.

[Otto123]

2025.02.17 17:36:08.494 5: MQTT Mosquitto

Ich weiß nicht, aber diese Zeilen sehen mir nach MQTT und nicht nach MQTT2_xxx aus. Im Log steht doch als erstes typischerweise der TYPE - und hier steht MQTT genau wie ein paar Zeilen später PRESENCE

[Tabadorer]

Kannst du vielleicht mal mit einem Tool wie MQTT Explorer mitlesen, was genau da übermittelt wird, wenn FHEM abstürzt?

Gute Idee, aber dadurch wird der Heuhaufen um die Nadel eher noch größer. Zumal man gar nicht weiß wonach man suchen soll. Es gibt ja nicht das eine, große fhem topic.

Code Auswählen Erweitern

mosquitto_sub -v -t '$SYS/broker/clients/active'
$SYS/broker/clients/active 48

mosquitto_sub -v -t '$SYS/broker/load/publish/received/1min'
$SYS/broker/load/publish/received/1min 991.07
$SYS/broker/load/publish/received/1min 990.02

mosquitto_sub -v -t '$SYS/broker/load/bytes/received/1min'
$SYS/broker/load/bytes/received/1min 178598.44
48 Clients senden da schon ne Menge Daten auf den Bus.

Ansonsten bietet es sich vielleicht ja auch an, erstmal mit einer "leeren" (also Minimalkonfiguration) fhem.cfg zu starten und erst nach und nach alles hinzuzufügen? Ggfs. auch mit abgeschaltetem autocreate von MQTT.

Ja so mache ich das gerade. Ich habe ja zum Glück ein Backup das 14 Tage alt ist und noch funktioniert. Erst wollte ich aus der defekten Konfig soviel rauslöschen bis es wieder geht. Aber es zeigt sich, das es besser ist die funktionierende solange zu aktualisieren, bis es dann nicht mehr funktioniert. Ich konnte mir mit dem Linux Befehl

Code Auswählen Erweitern

diff -u fhem_defekt.cfg fhem.funktioniert > unterschied.txt
eine Datei erstellen, die alle Unterschiede enthält. Das ist schon sehr hilfreich. Ich ändere ein paar Elemente in der Config, starte danach den Container immer neu durch und sehe was passiert. Wenn immer noch alles geht, sichere ich mit den Zustand als "LastKnownGood.cfg" damit bei einem Fehler nicht von ganz vorne anfangen muss.

2025.02.17 17:36:08.494 5: MQTT Mosquitto

Ich weiß nicht, aber diese Zeilen sehen mir nach MQTT und nicht nach MQTT2_xxx aus. Im Log steht doch als erstes typischerweise der TYPE - und hier steht MQTT genau wie ein paar Zeilen später PRESENCE

bei genauer Betrachtung hast du recht. Ich habe eine ULANZI TC001 Matrix Uhr mit der Awtrix3 Firmware. Und da es kein passendes Modul für die Ansteuerung gibt, sende ich nativ über ein DOIF die Daten. Hier ein Auszug aus dem gesamten DOIF.

Ich nutze das, damit ich für das Energiemanagment immer die Werte im Blick habe. ► siehe axtrix.gif

Code Auswählen Erweitern

set Mosquitto publish awtrix_2/custom/pv  [
{
"duration":4,
"text":"[SMASI:BatteryPower:d]",
"color":"#ff0000",
"icon":53570,
"lifetime":6,
"progress":"[SMASI:StateOfCharge:d]",
"progressC":"#00ff00",
"progressBC":"#555555"
},
{
"duration":2,
"text":"[SMASI:StateOfCharge]%",
"color":"#ffffff",
"lifetime":5,
"progress":"[SMASI:StateOfCharge:d]"
},
{
"duration":2,
"text":"[wetter_pro:temperaturedegree]°C",
"icon":2369,
"color":"#ffffff",
"lifetime":5
}]

Und seit ein paar Tagen habe ich in dem Zusammenhang das DOIF Attribut DOIF_Readings für mich entdeckt, da andernfalls die ganzen DOIF Bedingungen viel zu komplex werden. Und ich denke das ich bei einem Neustart nicht mehr alle Werte habe, die ich zur Laufzeit mal hatte. Ich habe zwar eine fhem.save angelegt, die scheint aber nur 99,9% abzudecken.

[Tabadorer]

Heureka! Fehler gefunden!

Ich habe einen öffentlichen Broker bei mir im Einsatz, wo ich mit

Code Auswählen Erweitern

set Mosquitto_public publish
 Daten hinschicke

Code Auswählen Erweitern

define Mosquitto_public MQTT broker.emqx.io:1883
attr Mosquitto_public icon mqtt
attr Mosquitto_public room Interfaces
#   DEF        broker.emqx.io:1883
#   DeviceName broker.emqx.io:1883
#   FD         33
#   FUUID      6633ad1f-f33f-2e01-01c5-f7abb354d4b87b99
#   FVERSION   00_MQTT.pm:0.249810/2021-09-16
#   NAME       Mosquitto_public
#   NOTIFYDEV  global
#   NR         276
#   NTFY_ORDER 50-Mosquitto_public
#   PARTIAL   
#   STATE      opened
#   TYPE       MQTT
#   buf       
#   eventCount 9
#   msgid      1
#   ping_received 1
#   timeout    60
#   READINGS:
#     2025-02-19 20:53:22   connection      active
#     2025-02-19 20:53:00   state           opened
#   messages:
#
setstate Mosquitto_public opened
setstate Mosquitto_public 2025-02-19 20:53:22 connection active
setstate Mosquitto_public 2025-02-19 20:53:00 state opened


Wenn man hier den Port auf den SSL Port 8883 ändert, startet fhem nach einem Neustart nicht mehr. Zur Laufzeit gibt es jedoch keine Fehler und der Status ist opened