…kleiner Nachtrag:
Das ist die Ausgabe von dmesg während symcon abstürzt:
[6205202.012231] Out of memory: Kill process 1593 (symcon) score 918 or sacrifice child
[6205202.012380] Killed process 1593 (symcon) total-vm:7081596kB, anon-rss:3699732kB, file-rss:0kB, shmem-rss:7940kB
[6205202.221135] oom_reaper: reaped process 1593 (symcon), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
[6210259.760254] symcon[11275]: segfault at 7f14e73d9a3c ip 000055e000ddd12b sp 00007ffcccbcdd90 error 4 in symcon[55dfff16f000+3bad000]
@geolin Bei mir hatte ich ähnliche Fehlermeldungen im Log bevor IPS abstürzt. (Gateway und zuviele Skripte, Speichermangel). Hatte die Logs leider gelöscht.
Da ich parallel Anpassungen gemacht habe, dachte ich ja zunächst, dass es mit zu vielen Fehlern zu tun hatte. Aktuell läuft IPS seit drei Tagen ohne Störung.
Ich habe gestern den Raspi neu aufgesetzt und IPS aus dem Backup wiederhergestellt. Da ich dafür einen 2. Raspi verwendet habe, waren keine 1Wire-Komponenten angeschlossen - und PIGPIO lief. Kaum war der Bus dran, ist es abgeschmiert.
Es hat sich dann herausgestellt, dass der Bus abschmiert, wenn ein Luftgütesensor dran hängt… Ist der abgeklemmt, läuft 1 Wire…
Die Latenzen habe ich trotzdem, z.B. beim Schalten von Lampen über das Shelly-Modul.
Moin,
das Problem mit den extremen Latenzen kann ich bestätigen.
es dauert (laut LOG) manchmal ~4 Sekunden bis ein Script gestartet wird…
Grüße
Dave
Hallo Peter1984.
Vielen Dank, dass Du Dir die Mühe machst 
Hab’ ein paar Fragen zu Deinem Test
…ist es abgeschmiert.
„es“ = IPS oder der 1-wire Bus ?
…dass der Bus abschmiert, wenn ein Luftgütesensor dran hängt… Ist der abgeklemmt, läuft 1 Wire…
Wie stellt du fest, dass der 1-wire Bus „abschmiert“ ?
Ist IPS dabei/anschließend super langsam ?
Und - wenn der 1-wire Bus nicht angeschlossen ist, ist dann alles normal (schnell) ?
Hast Du (zum TESTEN ob Ruhe reinkommt) das PiGPIO Modul auch mal länger deaktiviert ?
Was passiert dann?
Grüße
lueralba
„Es“ war in diesem Fall PIGPIO. Jetzt ist Ruhe im Karton, PIGPIO läuft und liest mir die Temperaturen aus dem 1-Wire Bus.
Habe heute - da ich keine Lust mehr auf meine aktuelle Bastel-Lösung habe - das 1-Wire Gateway von Symcon bestellt. Werde dann nochmal versuchen, den Luftgütesensor alleine direkt an I2C des Raspis zu hängen - gehe aktuell davon aus, das der Sensor hinüber ist.
Im Moment läuft IPS gut, bester Indikator war das Licht in der Küche, das über einen Shelly 1 das Licht über der Spüle per MQTT angeschaltet hat - hier gab es Verzögerungen von mehreren Sekunden, jetzt keine.
Ich weiß, es ist ungut, dass jetzt nicht ganz klar ist, ob es am abstürzenden PIGPIO oder an dem vermeintlich defekten Sensor lag, oder an was anderem. Interessant wäre dennoch, ob die anderen User mit Latenzen auch PIGPIO einsetzen?
Moin,
leider nein… ich nutze kein PIGPIO…
was auch komisch ist, ich habe die erhöhten Latenzen zum ersten Mal gestern abend bemerkt (da lief der Symcon Prozess bereits 13 tage), 1x bei einer Alexa Action und 1x bei einem Taster Script… dann wieder heute morgen bei einem Taster Script. Nach einem neustart des Docker Container konnte ich keine erhöhten Latenzen mehr feststellen…
Grüße
Dave
Heute Nacht mal wieder seit 3 Wochen ein (Komplett-)Absturz
die letzten Worte waren:
.............
07.10.2019 01:04:17 | 13322 | MESSAGE | Archive Control | Reaggregation for VariableID #11339 is in progress... 09/2019! (42953 rows)
07.10.2019 01:04:17 | 13322 | MESSAGE | Archive Control | Reaggregation for VariableID #11339 is in progress... 10/2019! (8557 rows)
07.10.2019 01:04:19 | 58854 | DEBUG | ScriptEngine | Skriptausführung - Ereignis: 11111 ~ Absender: Variable
07.10.2019 01:04:19 | 14994 | DEBUG | ScriptEngine | Skriptausführung - Ereignis: 21021 ~ Absender: Variable
07.10.2019 01:04:19 | 14994 | DEBUG | ScriptEngine | Skriptausführung - Ereignis: 21021 ~ Absender: Variable ~ Dauer: 25 ms
07.10.2019 01:04:19 | 14994 | WARNING | ScriptEngine | Result for Event 21021
0,116 kWh
07.10.2019 01:04:20 | 42036 | DEBUG | ScriptEngine | Skriptausführung - Ereignis: 17659 ~ Absender: TimerEvent
07.10.2019 01:04:20 | 00000 | CUSTOM | RS RRFC Home | #42036 ===> Fehler: CURL-Error bei Header-Abfrage PIC 0 '../201910062300_HES.png' (Error: Could not resolve host: www.wetteronline.de [6])
07.10.2019 01:04:20 | 00000 | CUSTOM | RS RRFC Home | #42036 ===> Fehler: CURL-Error bei Header-Abfrage PIC 0 '../201910062300_HES.png' (Error: Could not resolve host: www.wetteronline.de [6])
dass das Rainradar von RS unsauber läuft seit PHP-Update, sollte ja nicht das Problem sein, die Fehler werden ja abgefangen.
ID 14994 ist nur kleines Skript, was zwei V addiert und in dritte V schreibt. Quelle hiervon sind die Energieberichte. Deren Basis ist der Counter 11339 der gerade kurz vorher reaggr. wurde.
Also eine Berechnung mit einer Vari, die gerade aggregiert wurde.
Ansonsten war nichts in den Logs zu finden, was den Absturz provoziert hatte.
(zzt kein VoIP installiert) Rev IP-Symcon 5.3, Windows x64, 02.09.2019, 8b9cb5888709
Mein IPS steht kurz vor dem Absturz:
Ich habe es mit top einmal beobachtet:
Vorgestern war die Mem Usage bei ca. 10%, nun bei über 50%:
Ich setze die aktuelle IP-Symcon 5.2, Ubuntu, 25.09.2019, beadf93761da ein.
Werde nun mal symcon mit gdb starten inkl. Backtrace, da das Problem offensichtlich reproduzierbar ist.
Viele Grüße,
Georg
Hallo,
ich habe gestern auf die aktuelle IPS-Version aktualisiert sowie die anstehenden OS-Updates und den Server rebootet. IPS lief an.
Heute ist mir aufgefallen, das ich bei einem Modul ggfs ein Problem bei dem IPS-Restart bei System-Reboot habe und daher auf Shell-Ebene ein Symcon-Restart gemacht (sudo /etc/init.d/symcon restart).
und … IPS startet nicht mehr.
Dann habe ich ein erneutes Server-Reboot gemacht - IPS lief wieder an.
Erkennbarer Unterschied: der symcon-Prozess stürzt ab vor der Meldung *** IPS BETRIEBSBEREIT
07.10.2019 18:50:37 | 00000 | MESSAGE | Kernel | Initialisierung abgeschlossen
07.10.2019 18:50:37 | 00000 | MESSAGE | Kernel | Erstelle Nachrichten-Thread …
07.10.2019 18:50:37 | 00000 | MESSAGE | EventManager | Erstelle Ereignis-Thread…
07.10.2019 18:50:37 | 00000 | MESSAGE | TimerPool | Erstelle Ereignis-Thread…
07.10.2019 18:50:37 | 00000 | MESSAGE | DataServer | Starte Server…
07.10.2019 18:50:37 | 00000 | DEBUG | ScriptEngine | Skriptausführung (Text) - Länge: 149 ~ Absender: RunScript
07.10.2019 18:50:37 | 00000 | DEBUG | ScriptEngine | Skriptausführung (Text) - Länge: 0 ~ Absender: RunScript ~ Dauer: 25 ms
07.10.2019 18:50:37 | 00000 | DEBUG | ScriptEngine | Skriptausführung (Text) - Länge: 140 ~ Absender: RunScript
07.10.2019 18:50:37 | 00000 | DEBUG | ScriptEngine | Skriptausführung (Text) - Länge: 0 ~ Absender: RunScript ~ Dauer: 12 ms
07.10.2019 18:50:37 | 00000 | DEBUG | ScriptEngine | Skriptausführung (Text) - Länge: 160 ~ Absender: RunScript
07.10.2019 18:50:37 | 00000 | DEBUG | ScriptEngine | Skriptausführung (Text) - Länge: 0 ~ Absender: RunScript ~ Dauer: 13 ms
07.10.2019 18:50:37 | 00000 | DEBUG | ScriptEngine | Skriptausführung (Text) - Länge: 171 ~ Absender: RunScript
07.10.2019 18:50:37 | 27455 | MESSAGE | WebHook Control | Einstellungen gespeichert
07.10.2019 18:50:38 | 27538 | DEBUG | ScriptEngine | Skriptausführung - Ereignis: 38091 ~ Absender: Variable
07.10.2019 18:50:38 | 00000 | CUSTOM | Variablen auf Gateway setzen(27538) | sync variable „Ist es Tag“
07.10.2019 18:50:38 | 00000 | CUSTOM | MediolaServer::SetValueBoolean | set var ‚17‘ to value ‚true‘ on mediola.damsky.home => succeed
Was mich wundert ist, das Script laufen bevor IPS betriebsbereit ist - kann aber nicht sagen, ob das normal ist.
Ok, dachte ich, das teste ich mal und startet IPS im debugger
07.10.2019 18:55:41 | 12191 | VariableManager | [Räume\Gewächshaus\Tür (:0)\UNREACH] = true
[New Thread 0x7fff42bf1700 (LWP 2020)]
[Thread 0x7fff42bf1700 (LWP 2020) exited]
07.10.2019 18:55:41 | 00000 | ScriptEngine | Skriptausführung (Text) - Länge: 68257 ~ Absender: RunScript
07.10.2019 18:55:41 | 00000 | ScriptEngine | Skriptausführung (Text) - Länge: 0 ~ Absender: RunScript ~ Dauer: 15 ms
Thread 41 „symcon“ received signal SIGSEGV, Segmentation fault.
[Wechseln zu Thread 0x7fffce7fc700 (LWP 1967)]
0x000055555622f3eb in std::__detail::_Executor<__gnu_cxx::__normal_iterator<char const*, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::__cxx11::sub_match<__gnu_cxx::__normal_iterator<char const*, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > >, std::__cxx11::regex_traits<char>, true>::_M_dfs(std::__detail::_Executor<__gnu_cxx::__normal_iterator<char const*, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::__cxx11::sub_match<__gnu_cxx::__normal_iterator<char const*, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > >, std::__cxx11::regex_traits<char>, true>::_Match_mode, long) ()
(gdb)
und dann wollte ich IPS wieder zum laufen bringen … keine Chance, nun auch mit Reboot nicht mehr.
Nach einem (von > 10) weitere Reboots und läuft das System erstmal wieder, das ist aber macht auf mich eher den Eindruck, als wäre das relativ zufällig …
System-Info: IP-Symcon 5.2, Ubuntu, 25.09.2019, beadf93761da
Änderungen an IPS habe ich in den letzten Tagen nicht gemacht, nur eine Sicherheitsabfrage in einem Modul (eine Prüfung nur machen, wenn KR_READY).
Die habe ich erstmal zurückgenommen, kann aber nicht sagen, ob es daran liegt; „irgendwie“ traue ich mich nicht, das einfach zu testen ohne eine halbwegs sichere Idee, wie ich das im Zweifelsfall wieder hinbekomme.
Nun traue ich mich nicht, weiter zu testen, irgendwie hängt ja doch eine Menge an Bequemlichkeit an einem laufenden IPS
Ich nehme an, das ist eher etwas für @paresy?
Gruß
demel
Nachtrag: VOIP setze ich nicht ein
Hi demel
hast du irgendwelche automatischen Watchdog oder Reboot eingerichtet ?
Hatte mir mit so einer Konfiguration mal selbst ein Ei gelegt.- IPS brauchte nach einem Update minimal länger zum Reboot. Was passierte war das befor IPS noch komplett hochgefahren war und auf Events reagieren konnte lief schon mein Watchdog Script an und fuhr IPS wieder runter.
Hatte schon paresy und alle bösen Geister verflucht, bis ich bemerkte das ich selbst schuld an dauernden Reboots war.
gruß
bb
Hi,
nein, habe ich nicht.
danke
demel
Ich habe das Problem bei mir gelegentlich. Jetzt habe ich ein Powerhell-Script als Watchdog laufen, welches alle zwei Minuten den IPSServer-Dienst überwacht und ihn neu startet, falls er beendet wird. Läuft bis jetzt ganz gut.
Was mir auch noch aufgefallen ist:
Seit der 5.2 habe ich vermehrt Script-Fehler, weil die Ausführungszeit 30 Sekunden überschritten hat.
Diese Fehler hatte ich vor 5.2 nie und sie betreffen Skripte, die schon seit Jahren unverändert laufen und das normal in wenigen Millisekunden. Es sind auch keine besonderen Aktionen enthalten. Zum Teil einfach nur das Schreiben von Variablen.
Es ist aber auch kein Muster zu erkennen, wann die Skripte aufgrund ihrere Ausführungszeit abbrechen. Mal ist tagelang Ruhe, dann tritt es wieder vermehrt auf.
Vielleicht gibt es da ja einen Zusammenhang mit den Abstürzen.
Gruß
Slummi
Das kann ich bestätigen. Gestern morgen gingen die Raffstores nicht rauf, weil zu viele gleichzeitige Skripte aktiv waren (was nicht der Fall war, alle laufen superschnell durch im Normalfall) und die Queue verstopft war. Nur ein Reboot des Raspis hat geholfen.
Also ich habe ja immer mehr den Verdacht, dass da was mit PHP nicht stimmt. Kann man zu Testzwecken die php7ts.dll durch eine ältere von IPS 5.1 oder 5.0 austauschen oder läuft dann irgendwas nicht, weil irgendwelche Systemkomponenten von IPS neue Funktionen daraus brauchen?
Irgendwie muss man den Problemen doch auf die Spur kommen. Jahrelang lief IPS ohne den kleinsten Fehler oder Absturz (von normalen Bugs mal abgesehen) und jetzt häufen sich die Probleme.
Gruß
Slummi
ich habe den Fehler lokalisieren können, die ich hier gemeldet hatte:
Wenn ich in einem meiner Module, den auskommentierten DataFilter aktiviere gibt es reproduzierbar den in dem Post #50 beschriebenen Fehler.
public function ApplyChanges()
{
parent::ApplyChanges();
...
/*
$dataFilter = '.*id[^:]*:["]*' . $product_id . '.*';
$this->SendDebug(__FUNCTION__, 'set ReceiveDataFilter=' . $dataFilter, 0);
$this->SetReceiveDataFilter($dataFilter);
*/
...
}
… und jetzt, wo ich es eingekreist habe kommt mir die Stelle bekannt vor … das Problem hatte ich vor einigen Monaten schon an @Dr.Niels gemailt, der das nicht reproduzieren konnte 
Gruß
demel
@demel: Dein Server läuft unter Ubuntu und der Fehler ist gut reproduzierbar? Hättest du Zeit für eine Remote Debugging Session?
paresy
Ja & ja & ja. Beim mir geht’s Freitags und Montags immer ganz gut, allerdings nicht diesen Freitag (11.10.). Uhrzeit ist mir egal ab 8Uhr morgens.
Gruß
demel
Gibt es hier eigentlich was neues? Gab es die Remote Debugging Session?
Grüße
Stephan