IP-Symcon auf Raspi 3B+ sporadische Abstürze auch bei V5.3

Sporadisch stürzt IP-Symcon bei mir ab mit der Meldung:

„Unknown: Failed to open stream. zu viele offene dateien in ……“

In der Konsole erscheinen viele rote Ausrufezeichen. Das Meldungsfenster ist voller Warnungen.

Zu Beginn der Fehlermeldungen erfolgt ein Verweis auf „require_once (__generated.inc.php)“.
Diese Datei ist aber nicht in scripts vorhanden.

Nach Symcon Stop - Start läuft alles wieder normal bis zum nächsten mal…

Kennt noch jemand das Problem, was kann man tun?

Danke
tom2005

Das klingt so als wenn IP-Symcon (oder irgendwelche Module davon) zu viele gleichzeitige offene Dateien haben. Du könntest dies mit z.B. lsof mal versuchen zu analysieren. Zumindest kann du herausfinden welche Datei dort offen ist und dann herausfinden wer den Fehler verursacht.

paresy

Hallo paresy,

danke für die schnelle Antwort.
Ich habe lsof installiert, konnte aber keine verdächtigen Dateien finden.
Wo kann man die Anzahl der zulässig offenen Dateien ändern?

Gestern habe ich noch den Spezialschalter „LogfileVerbose“ deaktiviert, weil mein Logfile teilweise 240 MB angenommen hatte.
Heute scheinen es nur um die 25 MB zu werden. Was ist denn so der normale Wert?

Weiterhin habe ich die Roborock Instanz entfernt, z.Z. noch unbenutzt, aber zu Beginn des Fehlers aufgelistet.

Was hat es eigentlich mit der Fehlermeldungen „require_once ……(__generated.inc.php)“ auf sich?
Unter Scripts ist sie bei mir nicht vorhanden.

Werde weiter berichten ob der Fehler wieder kommt.

tom2005

Ein erneuter Absturz!

Nach dem ich heute um 0:30 das neueste Update auf meinen Raspi eingespielt habe kam um 4:32 der Absturz.

Das Log verzeichnet dazu folgende ständig wiederkehrende Meldung:

21.03.2020 04:32:33 | 30240 | WARNING | Register Variable | <br />
<b>Warning</b>: Unknown: failed to open stream: Zu viele offene Dateien in <b>Unknown</b> on line <b>0</b><br />
<br />
<b>Fatal error</b>: Unknown: Failed opening required ‚/usr/share/symcon/scripts/__autoinclude.inc.php‘ (include_path=’.:/var/lib/symcon/scripts’) in <b>Unknown</b> on line <b>0</b><br />

diese Einträge gingen bis zum Restart über Putty bis 7:08.
Das System ist in der Zeit weder über die Konsole noch über das Webfront zu erreichen.

Meine Bemühungen das Log zu verkleinern waren erfolgreich, heute nur noch ca. 5MB, aber leider hat es den Fehler nicht beeinflusst. (siehe dazu auch den letzen Beitrag)

Was kann ich noch tun, so ist IP-Symcon für mich sehr unsicher.
Das letzte Log könnte ich bei Bedarf bereit stellen.

Lg.
tom2005

Hi Tom,

könntest du vielleicht dies hier ausprobieren, sodass wir mehr Informationen zum Problem bekommen? https://www.symcon.de/forum/threads/27061-Debugging-für-Experten-(Raspberry-Pi-Linux)

Hast du den Pi seitdem neu gestartet? Falls nicht, kannst du mit ‚dmesg‘ mal schauen, ob es dort irgendwelche OOM (out of memory) Meldungen gibt?

paresy

Hallo Gemeinde ich bin ratlos,

ich bin nicht der einzige bei dem Symcon einfach seine Arbeit einstellt, wenn ich das Forum so lese.
Ich nutze nun seit 9 Jahren IP-Symcon und davon ca. 7 Jahre Vers. 3.4 unter Windows ohne nennenswerte Probleme.

Seit 2 Jahren bin ich auf Linux und Raspi und ich habe den Eindruck das nun alles schneller geht, aber auch das mit den ständigen Aktualisierungen und Modulen/Erweiterungen die Ausfall-Wahrscheinlichkeit nicht wirklich weniger wird.

Momentan versuche ich in den Spezialschaltern die Einstellungen zu optimieren, in der Hoffnung das zu geringe Limits meine Probleme hervorrufen.

Gibt es eigentlich eine Möglichkeit irgendwo die Anzahl von max. laufenden Threads auszulesen oder sollte man gleich alle Limits auf max. stellen?

Woran kann ich eigentlich erkennen ob die gesamte Laufzeit aller Threads zu groß geworden ist?

Frage: Log Eintrag …„failed to open stream: Zu viele offene Dateien“… könnte das bedeuten zu wenige Threads erlaubt, oder zu viele gleichzeitig?

Danke schon mal für ein paar weitere Anregungen

tom2005

Hi paresy,

wir haben uns gerade überschnitten.

  • der Pi wurde nicht neu gestartet.
  • dmsg zeigt keine OOM an.

Das Debugging werde ich heute mal installieren, hoffentlich lässt sich die Ursache finden.

Es ist frustrierend und der WAF sinkt mächtig

tom2005

Konntest du mit dem Debugger schon etwas herausfinden?

paresy

Hi paresy,

habe nichts mehr gefunden, aber bei den Versuchen mein Voip-Problem zu lösen habe ich die Thread Count hochgesetzt und nun eigentlich bei „40“ nicht mehr diese Meldung

Unknown: failed to open stream: Zu viele offene Dateien in <b>Unknown</b>

Ich würde sagen das Problem ist damit gelöst, danke.

Vielleicht findest du Zeit meinen Thread "VoIP-Modul nach Symcon Absturz hängt bei „Registrieren…“ mal zu kommentieren.

Dort komme ich momentan gar nicht weiter.

Danke tom2005

Hallihallo,
ich möchte mich einmal mit an die Absturzprobleme von Symcon 5.3 anhängen.
Ich habe Anfang Februar ein Hutschienengehäuse für meinen RPI4 gekauft, seitdem läuft mein System dort drin. Ob Zufall oder nicht, seitdem habe ich allerdings auch Probleme mit regelmäßigen Abstürzen von Symcon.
Zunächst einmal zum System:
Raspberry PI 4b+ mit 4GB
RPI-RF-MOD Funkmodul
Darauf laufen DEBMATIC (sehr stabil) und SYMCON 5.3 (leider nicht mehr so stabil).

Seither habe ich zwische 3 Abstürze täglich bis einen Absturz alle 2 bis 3 Tage.
Ich bin ständig auf der Suche nach der Ursache, kann sie aber nicht finden. Das normale Symcon-Log zeigt vor dem Crash unterschiedlichste Einträge und ich habe versucht, durch Entfernung unnötiger Module und Heraufsetzen der maximal mögliche gleichzeitigen Threads auf 30 Abhilfe zu schaffen (ich hatte viele Einträge „too many trheads… dropping“ o.ä. im Log). Ohne Erfolg (ok, doch, die Meldung von too many threads ist weg).
Auffällig ist, dass die Abstürze häufig zu einer ähnlichen Uhrzeit erfolgen (die letzten beide um 00:36) und öfter mal der Eintrag " 27677 | WARNING | Client Socket | Error reading: End of file" als letzter Logeintrag zu finden ist. Es handelt sich hierbei um das Logitech Harmony Modul aus dem Symcon Store. Zufall? Vielleicht, denn nicht immer ist dieser Eintrag am Ende zu finden.
Das Crashlog sieht immer fast gleicht aus, nur die Threadnummer ist unterschiedlich:
Stack trace (most recent call last) in thread 918:
#2 Object „/lib/arm-linux-gnueabihf/libc.so.6“, at 0xb6c6812f, in
#1 Object „/usr/bin/symcon“, at 0xe86237, in backward::SignalHandling::sig_handler(int, siginfo_t*, void*)
#0 Object „/usr/bin/symcon“, at 0xe85643, in backward::SignalHandling::handleSignal(int, siginfo_t*, void*)

Ich habe mir für die CCU (debmatic) einen Watchdog geschrieben, der den Symcondienstes auf dem RPI4 überprüft und bei Absturz einen Reboot durchführt. Ich hatte auch schon mit einem „simplen“ Neustart des Symcon Dienstes (symcon restart oder start) gearbeitet, musste aber feststellen, dass Symcon nach einem Neustart nicht dauerhaft stabil lief und sehr schnell wieder abstürzte.

Ich habe jetzt einmal das weiter oben in diesem Forum angegebene Debugging gestartet und bin gespannt, was sich hier ergibt.
„failed to open stream: Zu viele offene Dateien“ ist bei mir bisher übrigens nicht aufgetaucht. VoIP nutze ich nicht.

Andreas

Hi Andreas,

das ist ja sehr ärgerlich. Ich habe deine Crash Reports auch gesehen - aber wie du schon sagst enthalten die nichts nützliches. Ich hoffe somit, dass du mit GDB einen guten Stacktrace bekommst, sodass wir der Ursache endlich auf die Spur kommen!

paresy

Tatsächlich lief Symcon hier bis zu dem Umzug sehr stabil.
Ich habe mal ABSTUERZE.zip hochgeladen. Diese enthält die Logdateien der Abstürze seit 27.03.
Vielleicht fällt dir irgendetwas darin auf?

So, das ist schon mal schief gegangen.
Irgendwann gab es keine Ausgaben mehr in gdb (war eingefroren), keine Prompt und keine Möglichkeit mehr, die nötigen Befehle einzugeben, die Logdatei schreiben zu lassen.
Angeblich lief der Symcon Service noch, es gab jedoch keine Möglichkeit mehr darauf zuzugreifen (weder IPS-View noch IPS Konsole).
Einzige Möglichkeit war, GDB zu killen. Danach lief auch der Symcon Service nicht mehr und nach und nach stiegen dann auch debmatic und der SSH Zugriff aus.
Ich musste den RPI ganz vom Strom trennen und neu starten und probiere das Ganze noch mal neu.

Kurz vor dem Crash hat übrigens das Connect Modul von Symcon begonnen, Meldungen zu produzieren:

02/04/20 22:10:16 | 57512 | DEBUG | Connect Control | ssh_socket_unbuffered_write: Enabling POLLOUT for socket
02/04/20 22:10:16 | 57512 | DEBUG | Connect Control | packet_send2: packet: wrote [len=28,padding=13,comp=14,payload=14]
02/04/20 22:10:24 | 10866 | DEBUG | VariableManager | [Sensoren\Temperatur\Temperatursensor (Eisschrank)\WEATHER\TEMPERATURE] = -22.1000000000
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | ssh_packet_socket_callback: packet: read type 90 [len=76,padding=9,comp=66,payload=66]
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | ssh_packet_process: Dispatching handler for packet type 90
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | ssh_packet_channel_open: Clients wants to open a forwarded-tcpip channel
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | ssh_message_channel_request_open_reply_accept_channel: Accepting a channel request_open for chan 0
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | ssh_socket_unbuffered_write: Enabling POLLOUT for socket
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | packet_send2: packet: wrote [len=28,padding=10,comp=17,payload=17]
02/04/20 22:10:34 | 57512 | MESSAGE | Connect Control | [44] Created new channel
02/04/20 22:10:34 | 57512 | MESSAGE | Connect Control | [44] Connecting to 127.0.0.1:3777…
02/04/20 22:10:34 | 57512 | MESSAGE | Connect Control | [44] Connected to local server
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | ssh_packet_socket_callback: packet: read type 94 [len=220,padding=12,comp=207,payload=207]
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | ssh_packet_process: Dispatching handler for packet type 94
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | channel_rcv_data: Channel receiving 198 bytes data in 0 (local win=32000 remote win=24576)
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | channel_default_bufferize: placing 198 bytes into channel buffer (stderr=0)
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | channel_rcv_data: Channel windows are now (local win=31802 remote win=24576)
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | ssh_socket_unbuffered_write: Enabling POLLOUT for socket
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | packet_send2: packet: wrote [len=28,padding=18,comp=9,payload=9]
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | grow_window: growing window (channel 86:0) to 1280000 bytes
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | ssh_channel_read_timeout: Read (198) buffered : 198 bytes. Window: 1280000
02/04/20 22:10:34 | 57512 | MESSAGE | Connect Control | [44] Reading remote data… 198 bytes
02/04/20 22:10:34 | 57512 | MESSAGE | Connect Control | [44] Writing remote data…
02/04/20 22:10:34 | 57512 | MESSAGE | Connect Control | [44] Writing remote data… 198 bytes
02/04/20 22:10:34 | 57512 | MESSAGE | Connect Control | [44] Reading local data… Limit: 65536
02/04/20 22:10:34 | 57512 | MESSAGE | Connect Control | [44] Reading local data… 153 bytes
02/04/20 22:10:34 | 57512 | MESSAGE | Connect Control | [44] Write local data… Available: 153, Window: 24576
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | ssh_socket_unbuffered_write: Enabling POLLOUT for socket
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | packet_send2: packet: wrote [len=172,padding=9,comp=162,payload=162]
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | channel_write_common: channel_write wrote 153 bytes
02/04/20 22:10:34 | 57512 | MESSAGE | Connect Control | [44] Write local data… 153 bytes
02/04/20 22:10:34 | 57512 | MESSAGE | Connect Control | Connection check successful!
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | ssh_packet_socket_callback: packet: read type 96 [len=12,padding=6,comp=5,payload=5]
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | ssh_packet_process: Dispatching handler for packet type 96
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | channel_rcv_eof: Received eof on channel (86:0)
02/04/20 22:10:34 | 57512 | MESSAGE | Connect Control | [44] Reading remote data… EOF
02/04/20 22:10:34 | 57512 | MESSAGE | Connect Control | [44] Reading local data: Closed
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | ssh_socket_unbuffered_write: Enabling POLLOUT for socket
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | packet_send2: packet: wrote [len=12,padding=6,comp=5,payload=5]
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | ssh_channel_send_eof: Sent a EOF on client channel (86:0)
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | ssh_socket_unbuffered_write: Enabling POLLOUT for socket
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | packet_send2: packet: wrote [len=12,padding=6,comp=5,payload=5]
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | ssh_channel_send_eof: Sent a EOF on client channel (86:0)
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | packet_send2: packet: wrote [len=12,padding=6,comp=5,payload=5]
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | ssh_channel_close: Sent a close on client channel (86:0)
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | ssh_socket_unbuffered_write: Enabling POLLOUT for socket
02/04/20 22:10:34 | 57512 | MESSAGE | Connect Control | [44] Freed old channel. Remaining channels: 0
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | ssh_packet_socket_callback: packet: read type 97 [len=12,padding=6,comp=5,payload=5]
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | ssh_packet_process: Dispatching handler for packet type 97
02/04/20 22:10:34 | 57512 | DEBUG | Connect Control | channel_rcv_close: Received close on channel (86:0)
02/04/20 22:10:44 | 29313 | MESSAGE | VariableManager | [Sensoren\Luxmeter\Luxmeter West\LUXMETER\LUX] = 1.7000000000
02/04/20 23:13:31 | 00000 | MESSAGE | Settings | Writing settings…
02/04/20 23:13:31 | 13909 | ERROR | TimerPool | Monitor PI-SERVER (HMON_UpdateTimer): Waiting for script result timed out
02/04/20 23:13:31 | 17394 | ERROR | FlowHandler | Could not forward data to instance #17394: Waiting for script result timed out

Prüf mal deine SD-Karte und Datensystem „df -h“

Sieht alles normal aus.

Filesystem Size Used Avail Use% Mounted on
/dev/root 59G 3.8G 53G 7% /
devtmpfs 1.8G 0 1.8G 0% /dev
tmpfs 2.0G 0 2.0G 0% /dev/shm
tmpfs 2.0G 18M 1.9G 1% /run
tmpfs 5.0M 8.0K 5.0M 1% /run/lock
tmpfs 2.0G 0 2.0G 0% /sys/fs/cgroup
/dev/sda1 30G 8.4G 22G 29% /media/usbstick
/dev/mmcblk0p1 253M 53M 200M 21% /boot
tmpfs 391M 0 391M 0% /run/user/1000
//192.168.178.2/symcon 391G 216G 176G 56% /mnt/symcon

Toll,
seitdem ich Symcon im Debugger gestartet habe (mit Option A der Anleitung), läuft es jetzt schon seit fast 48 Stunden klaglos durch.
Einzige Änderung zu meinem „instabilen“ System: ich hatte Instanzen aus dem Modul „ipsymcon-phpmodule-by-Tommi“ für AVM Schaltaktoren angelegt. Diese habe ich nun gelöscht, da ich sie derzeit nicht verwende.

Das gerne mal so, dass es im Debugger länger dauert, bis etwas passiert/abstürzt :slight_smile:

paresy

ich wüßte jetzt auf Anhieb nicht, was an den AVM Modul für Abstürze sorgen könnte. Da ist eigentlich nur ein HTTP Zugriff auf die Fritzbox und ein 5min Timer drin. Das sind alles Standardcalls und seit langen unverändert. Bei mir läuft das auch auf einem Rasbpi3 ohne Probleme

Wenn trotzdem noch was auffällt, gerne Bescheid sagen.

Tommi

Ich glaube eigentlich auch nicht, dass das die Ursache ist. Ich bin aus irgend einem Grund darauf gekommen, den ich gerade vergessen habe und nicht mehr nachvollziehen kann.
Eventuell war es eine negative Rückmeldung oder Fehölermeldung, da die beiden Schaltsteckdosen, die ich mal an meiner Fritzbox betrieben habe, derzeit abgeklemmt sind.

@paresy
Danke, habe alles gefunden und den Umstieg ausgeführt.
UInd was soll ich sagen? Es hat knapp 2 Stunden gedauert, da gab es den ersten Crash.
Mir fällt auf, dass der letzte Entrag im Log vor dem Crash SEHR oft
05/04/20 15:11:20 | 27677 | WARNING | Client Socket | Error reading: End of file
lautet. Hierbei handelt es sich um den Client Socket für die Logitech Harmony Fernbedienung aus dem Modul von Fonzo & Zapp.
Ob hier eine Unverträglichkeit meiner Harmony (Harmony 2400pro) besteht?
Ich bin jetzt ein paar Tage unterwegs, werde danach aber mal testen, was passiert, wenn ich das Modul rausnehme.