FHEM Perl auf 100% CPU nach TCP interface disconnect.

[tomleitner]

Hallo,

Ich betreibe meinen FHEM server auf einer sehr performanten Hardware (ODROID N2) und habe eigentlich keine Performance Probleme. Ich habe einige Devices (in Summe ca. 30 Stück MQTT) aber auch ein paar alte COC und CUL Dinger. Einen CUL 433 MHz Stick habe ich an einem externen Raspi über ser2net angebunden. Der Raspi ist über WLAN mit dem Netz verbunden.
So ist das Ding definiert:

Code Auswählen Erweitern

defmod CUL433 CUL 192.168.1.6:2004 1445
attr CUL433 alias CUL433
attr CUL433 rfmode slowRF
attr CUL433 room Device Status
attr CUL433 showtime 1

Klappt alles hervorragend. Nun habe ich in den letzten Tagen folgendes Problem: ca. alle paar Tage ist FHEM komplett TOT! Das Web Interface reagiert nicht mehr und keine Aktionen werden mehr ausgelöst. "top" zeigt dass der "perl" Prozess mit 100% CPU läuft.  Wenn man den Prozess killt passiert nichts. Wenn man ihn mit "kill -9" killt taucht sofort ein neuer Perl Prozess auf der ebenfalls 100% CPU braucht.  "systemctl stop fhem" bleibt hängen. Erst wenn ich danach den Perl Prozess kille dann läuft "systemctl restart fhem" durch und es geht wieder alles.

Im Logfile steht:

Code Auswählen Erweitern

2019.12.19 08:49:29 3: CUL433: Unknown code Port already in use, help me!
2019.12.19 08:49:29 1: 192.168.1.6:2004 disconnected, waiting to reappear (CUL433)
2019.12.19 08:49:30 1: Wassersensor_Keller has timed out
2019.12.19 08:49:30 1: Wassersensor_Heizkeller has timed out
2019.12.19 08:49:31 3: TelegramBot_Callback Telegram: Digest: Number of poll failures on 2019-12-18 is :0:
2019.12.19 08:49:37 3: CUL433 IT_set: EsstischLampe off
2019.12.19 08:49:38 2: IT IODev device didn't answer is command correctly:   raw => No answer
2019.12.19 08:49:44 3: CUL433 IT_set: EsstischLampe on
2019.12.19 08:49:44 2: IT IODev device didn't answer is command correctly:   raw => No answer
2019.12.19 08:49:47 3: CUL433 IT_set: EsstischLampe off
2019.12.19 08:49:47 2: IT IODev device didn't answer is command correctly:   raw => No answer
2019.12.19 08:49:55 3: CUL433 IT_set: EsstischLampe on
2019.12.19 08:49:55 2: IT IODev device didn't answer is command correctly:   raw => No answer


Jedes Mal wenn das Problem auftritt ist eine Meldung wie:

Code Auswählen Erweitern

2019.12.17 04:50:20 1: 192.168.1.6:2004 disconnected, waiting to reappear (CUL433)

im Logfile. Kann sein das es hier ein Problem gibt?

Ich habe überigns den externen raspi auf 192.168.1.6 geprüft und er läuft problemlos. Der Port 2004 ist auch offen. Habe ihn auch restartet und gewartet dass sich FHEM neu verbindet. Tut es aber nicht. Erst nach dem "systemctl restart fhem" ist wieder alles ok?

Danke ...

Tom

[rudolfkoenig]

Gibt es mehrere perl Prozesse?
Was liefert "strace -p <fhem-pid>" zurueck?

[tomleitner]

Gibt es mehrere perl Prozesse?

Nein, nur einen!

Was liefert "strace -p <fhem-pid>" zurueck?

Habe ich schon probiert. Liefert super viel Output und auf den ersten Blick nichts auffälliges. Schwer ein Muster herauszulesen. Sollte es wieder auftreten werde ich den Output mal abspeichern ...

Habe heute testweise probiert auf dem Raspi ein "systemctl restart ser2net" zu machen. Das klappt wunderbar. Im FHEM Log steht dann:

Code Auswählen Erweitern

2019.12.19 10:48:51 1: 192.168.1.6:2004 disconnected, waiting to reappear (CUL433)
2019.12.19 10:48:51 1: 192.168.1.6:2003 disconnected, waiting to reappear (COC)
2019.12.19 10:49:52 3: COC: Possible commands: mbCFiAZGMKbRTVWXefltux
2019.12.19 10:49:52 1: 192.168.1.6:2003 reappeared (COC)
2019.12.19 10:49:53 3: CUL433: Possible commands: BbCFiAZNkGMKUYRTVWXefmLltux
2019.12.19 10:49:53 1: 192.168.1.6:2004 reappeared (CUL433)
2019.12.19 10:51:18 4: CUL_Parse: COC K01062167F5 -79.5


Wie Du siehst hab ich auf dem Raspi zwei Interfaces via ser2net: Einen COC und einen CUL433 ... für den Fall dass das eine Rolle spielt ...

Ich hab nun mal den Verbose Level beider Interfaces auf 4 hinaufgesetzt im FHEM ... vielleicht sehe ich dann was ...

Danke

[Frank_Huber]

im global den DNS Server gesetzt?
ansonsten könnte alles was DNS benutzt blockieren.

[tomleitner]

im global den DNS Server gesetzt?
ansonsten könnte alles was DNS benutzt blockieren.

Danke, aber sollte das nicht über das System (also /etc/resolv.conf) gehen? Wie auch immer: Ich habs nun gesetzt ... mal schaun ob es etwas bewirkt ...

Danke.

[Wernieman]

Alternativ nur IPs verwenden und keine DNS-Daten ...

[rudolfkoenig]

Ich fuerchte ihr loest ein hier nicht vorhandenes Problem: beim Ausfall des DNS-Servers kann die Namensaufloesung beim Netzwerk-Verbindungsaufbau, ohne dnsServer Attribut, FHEM zwar blockieren, aber niemals 100% CPU Last erzeugen.

[tomleitner]

Hallo,

Leider habe ich das Problem immer noch. Jedoch nun folgendes entdeckt: Wenn dieser Fehlerzustand eintritt, scheint FHEM offenbar irgendwo ein Sleep o.ä. abzugehen in einer Eventloop o.ä. Jedenfalls habe ich folgendes Statement in meiner fhem.cfg:

Code Auswählen Erweitern


define Alarmanlage_Poll at +*00:10:00 set Alarmanlage updateSensor ALL


d.h. alle 10 Minuten wird hier was getan. Im oben beschriebenen Fehlerfall aber sehen ich dann folgendes im Log:

Code Auswählen Erweitern

2020.05.15 17:59:58 3: MQTT2_DEVICE set Alarmanlage updateSensor ALL
2020.05.15 17:59:58 3: MQTT2_DEVICE set Alarmanlage updateSensor ALL
2020.05.15 17:59:58 3: MQTT2_DEVICE set Alarmanlage updateSensor ALL
2020.05.15 17:59:58 3: MQTT2_DEVICE set Alarmanlage updateSensor ALL
2020.05.15 17:59:58 3: MQTT2_DEVICE set Alarmanlage updateSensor ALL
2020.05.15 17:59:58 3: MQTT2_DEVICE set Alarmanlage updateSensor ALL
2020.05.15 17:59:58 3: MQTT2_DEVICE set Alarmanlage updateSensor ALL
2020.05.15 17:59:58 3: MQTT2_DEVICE set Alarmanlage updateSensor ALL
2020.05.15 17:59:58 3: MQTT2_DEVICE set Alarmanlage updateSensor ALL
2020.05.15 17:59:58 3: MQTT2_DEVICE set Alarmanlage updateSensor ALL


d.h. der Timer spielt total verrückt und löst permanent aus!!  Im normalfall sehe ich diese Meldung eben nur alle 10 Minuten im Log ... so wie es sein sollte. Im Fehlerfall aber permanent und offenbar spielen dann alle Timer verrückt und FHEM geht auf 100% CPU.

Kann sich das jemand erklären?

Danke // Tom

[rudolfkoenig]

Die Uhr des Rechners spielt verrueckt.

[Wernieman]

Was sagt (als root) ein

Code Auswählen Erweitern

hwclock; date

[tomleitner]

Das ist im Normalzustand:

Code Auswählen Erweitern

root@ha:~# hwclock; date
2020-05-16 16:45:05.804750+0200
Sat May 16 16:45:04 CEST 2020


Allerdingts: Warum sollte die Uhr verrückt spielen ... um das Problem zu beheben starte ich ja FHEM neu ... warum sollte dadurch die System Uhr beeinflusst werden?

[herrmannj]

fhem ist top aktuell ?

[Wernieman]

Kannst Du uns mal ein List des Devices geben, welches "set Alarmanlage updateSensor ALL" absendet?

[herrmannj]

Rudi hat vor kurzem deep recursionen in ganz speziellen Fällen beseitigt. Das würde imho gut zu dem beschriebenen Verhalten passen (100% Last)

[tomleitner]

Danke für eure Antworten. Ja, FHEM ist top aktuell. Hier ist ein List des devices das diesen Befehl absetzt, allerdings gebe ich zu bedenken dass es nicht dieses device alleine ist das im Fehlerfall verrückt spielt ... es sind alle ähnlichen devices die nicht mehr gehen ...

Code Auswählen Erweitern


Internals:
   COMMAND    set Alarmanlage updateSensor ALL
   DEF        +*00:10:00 set Alarmanlage updateSensor ALL
   FUUID      5cc68981-f33f-44cf-aca3-08cac86b28b75d51
   NAME       Alarmanlage_Poll
   NR         841
   NTM        23:55:16
   PERIODIC   yes
   RELATIVE   yes
   REP        -1
   STATE      Next: 23:55:16
   TIMESPEC   00:10:00
   TRIGGERTIME 1589666116.47433
   TRIGGERTIME_FMT 2020-05-16 23:55:16
   TYPE       at
   Helper:
     DBLOG:
       state:
         logDb:
           TIME       1589665516.47945
           VALUE      Next
   READINGS:
     2020-05-16 23:45:16   state           Next: 23:55:16
Attributes:
   alias      Alarmanlage_Poll