IP-Symcon v4.3: Dienst beendet erratisch ohne Hinweis im Log

Hallo,

leider habe ich eine ähnliche Situation. IP-Syscon lief plötzlich nicht mehr und ich bekomme folgende Fehlermeldung:

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x644ff430 (LWP 7298)]
0x00329f48 in ALLUniversal::UpdateValues() ()
(gdb) bt
#0 0x00329f48 in ALLUniversal::UpdateValues() ()
#1 0x00b08354 in std::thread::_Impl<std::_Bind_simple<IPSTimerPool::processTimers()::{lambda()#1} ()> >::_M_run() ()
#2 0x768f8348 in ?? () from /usr/lib/arm-linux-gnueabihf/libstdc++.so.6
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Habe auch schon IP-Symcon deinstalliert und wieder installiert, mit der Beta-Version versucht, aber der Dienst startet einfach nicht mehr…

Der Log endet mit folgendem Eintrag:

01:38:13 | 54410 | MESSAGE | HUEGroup | Creating…
01:38:13 | 00000 | DEBUG | ScriptEngine | Executing Text (Length: 159) ~ Sender: RunScript
01:38:13 | 00000 | DEBUG | ScriptEngine | Executed Text (Length: 0) ~ Sender: RunScript
01:38:13 | 00000 | DEBUG | ScriptEngine | Executing Text (Length: 165) ~ Sender: RunScript
01:38:13 | 00000 | DEBUG | ScriptEngine | Executed Text (Length: 0) ~ Sender: RunScript
01:38:13 | 00000 | MESSAGE | Kernel | Initializing Complete
01:38:13 | 00000 | MESSAGE | Kernel | Creating message thread…

Vielen Dank für jedwede Unterstützung.

:expressionless: Klaus

@Klaus: Das Problem sollte bereits in der aktuellen Beta-Version gelöst sein.
@home: Hast du evtl. schon neue Infos welche Variable es bei dir betrifft?

paresy

… und dann sind wir ab heute bei 75% aller Graphen…

Status bisher: mit den 50% der Graphen die die letzten 2 Wochen aktiv waren ist das „Phänomen“ nicht eingetreten…

stay tuned… am 9. Oktober gibts das nächste Update… es sei denn wir haben vorher einen „Treffer“.

homa

Hallo,

Ich habe auch seit meinem letzen Update (vor ca 1,5 Wochen) regelmäßig Abstürze von IP-Symcon (läuft ca einen Tag). Ich habe auch einen Raspi und noch IPS-Studion laufen. Ich hatte leider noch keine Zeit für Fehleranalyse. Beim ersten überfliegen der Linux-Logs und Symcon-Logs habe ich nichts auffälliges gefunden. Bei Gelegenheit versuche ich nochmal mehr rauszufinden.

viele Grüße
cervicor

Für Linux würde mich ein Backstrace interessieren. Schau mal bitte hier: Debugging für Experten (Raspberry Pi, Linux)

Nutzt du ALLNET Geräte?

paresy

Hallo paresy,

ich bin leider erst heute dazu gekommen ein BackTrace zu machen. Ich hoffe es hilft weiter.



Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x6baff430 (LWP 24017)]
0x003e3a98 in ELVFHZ::ParseBuffer(unsigned int) ()
(gdb) bt
#0  0x003e3a98 in ELVFHZ::ParseBuffer(unsigned int) ()
#1  0x003e5c80 in ELVFHZ::ReceiveData(IPSData const&) ()
#2  0x00a3285c in IPSFlowHandler::SendDataToChildren(unsigned short, IPSData const&) ()
#3  0x00682bcc in IOSerialPort::completedReading(std::shared_ptr<std::array<char, 4096u> >, unsigned int, boost::system::error_code const&) ()
#4  0x00686624 in boost::asio::detail::descriptor_read_op<boost::asio::mutable_buffers_1, boost::_bi::bind_t<void, boost::_mfi::mf3<void, IOSerialPort, std::shared_ptr<std::array<char, 4096u> >, unsigned int, boost::system::error_code const&>, boost::_bi::list4<boost::_bi::value<IOSerialPort*>, boost::_bi::value<std::shared_ptr<std::array<char, 4096u> > >, boost::arg<2> (*)(), boost::arg<1> (*)()> > >::do_complete(boost::asio::detail::task_io_service*, boost::asio::detail::task_io_service_operation*, boost::system::error_code const&, unsigned int) ()
#5  0x0035d5c0 in boost::asio::detail::epoll_reactor::descriptor_state::do_complete(boost::asio::detail::task_io_service*, boost::asio::detail::task_io_service_operation*, boost::system::error_code const&, unsigned int) ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb) 

Ach so - ALLNET-Geräte benutze ich nicht.

vielen Dank
cervicor

Hallo cervicor,

wir haben das Problem nachstellen können. Nachher kommt ein entsprechender Fix auf den Beta-Kanal.

Es wurden wohl Nachrichten verschickt, die zu kurz waren. Nach Protokoll muss eine FHZ-Nachricht mindestens 4 Byte lang sein. Dies wurde allerdings von unserer Seite her bisher nicht geprüft, so dass ungültige, kürzere Nachrichten Fehler verursachen konnten. Dies haben wir jetzt behoben und zu kurze Nachrichten werden korrekt abgelehnt.

Danke Dr. Niels,

Ich hatte nun seit gestern keinen Absturz mehr und dachte das Problem läge woanders. Ich hatte gestern noch in einem Workflow in IPS-Studio einen Fehler (Situation muss ich separat klären) gefunden und geändert. Ich dachte das Problem kommt aus diesem Bereich. Der hat aber mit FHZ nichts zu tun (dort wird ein z-Wave Schalter betätigt). Auch sollte so ein Fehler ja auch nicht zu einem Absturz führen…

Ich muss also die nächste Beta einspielen um den Fehler zu korrigieren?

Danke und Gruß
cervicor

Ich leide leider auch unter Crashs … Neustart war gestern Abend nach gleichem Fehler - heute Mittag um 16 Uhr war leider wieder der obige Fehler zu sehen und ich muss den Server neustart.

Ich habe in der letzten Zeit nur Charts ins Webfront eingebunden und ein größeres Curl Script für den Wechselrichter laufen

16:20:02 | 26269 | WARNING | ScriptEngine | Ergebnis für Ereignis 47477
403,33333333333
16:20:02 | 53500 | DEBUG | ScriptEngine | Skriptausführung - Ereignis: 48459 ~ Absender: TimerEvent
16:20:02 | 53500 | DEBUG | ScriptEngine | Skript ausgeführt - Ereignis: 48459 ~ Absender: TimerEvent
16:20:02 | 47599 | DEBUG | ScriptEngine | Skriptausführung - Ereignis: 49099 ~ Absender: TimerEvent
16:20:02 | 47599 | DEBUG | ScriptEngine | Skript ausgeführt - Ereignis: 49099 ~ Absender: TimerEvent
16:20:02 | 40951 | DEBUG | ScriptEngine | Skriptausführung - Ereignis: 51573 ~ Absender: TimerEvent
16:20:02 | 40951 | DEBUG | ScriptEngine | Skript ausgeführt - Ereignis: 51573 ~ Absender: TimerEvent
16:20:02 | 18945 | DEBUG | ScriptEngine | Skriptausführung - Ereignis: 54572 ~ Absender: TimerEvent
16:20:02 | 18945 | DEBUG | ScriptEngine | Skript ausgeführt - Ereignis: 54572 ~ Absender: TimerEvent
16:20:02 | 18945 | WARNING | ScriptEngine | Ergebnis für Ereignis 54572
Aussen 14,2 Küche 23 Ziel Temperatur 21,5 Zeit 16:20 Heizung Aus
16:20:02 | 10606 | DEBUG | ScriptEngine | Skriptausführung - Ereignis: 58165 ~ Absender: Variable
16:20:02 | 10606 | DEBUG | ScriptEngine | Skript ausgeführt - Ereignis: 58165 ~ Absender: Variable
16:20:02 | 17769 | DEBUG | ScriptEngine | Skriptausführung - Ereignis: 50441 ~ Absender: Variable
16:20:02 | 17769 | DEBUG | ScriptEngine | Skript ausgeführt - Ereignis: 50441 ~ Absender: Variable
16:20:02 | 31861 | DEBUG | ScriptEngine | Skriptausführung - Ereignis: 49408 ~ Absender: Variable
16:20:02 | 31861 | DEBUG | ScriptEngine | Skript ausgeführt - Ereignis: 49408 ~ Absender: Variable
16:20:02 | 33721 | DEBUG | ScriptEngine | Skriptausführung - Ereignis: 11798 ~ Absender: Variable
16:20:02 | 33721 | DEBUG | ScriptEngine | Skript ausgeführt - Ereignis: 11798 ~ Absender: Variable
16:20:02 | 12470 | DEBUG | ScriptEngine | Skriptausführung - Ereignis: 29889 ~ Absender: Variable
16:20:02 | 12470 | DEBUG | ScriptEngine | Skript ausgeführt - Ereignis: 29889 ~ Absender: Variable
16:20:02 | 57694 | DEBUG | ScriptEngine | Skriptausführung - Ereignis: 17339 ~ Absender: Variable
16:20:02 | 57694 | DEBUG | ScriptEngine | Skript ausgeführt - Ereignis: 17339 ~ Absender: Variable
16:20:02 | 14794 | DEBUG | ScriptEngine | Skriptausführung - Ereignis: 16851 ~ Absender: Variable
16:20:02 | 14794 | DEBUG | ScriptEngine | Skript ausgeführt - Ereignis: 16851 ~ Absender: Variable
16:20:02 | 28703 | DEBUG | ScriptEngine | Skriptausführung - Ereignis: 16837 ~ Absender: Variable
16:20:02 | 28703 | DEBUG | ScriptEngine | Skript ausgeführt - Ereignis: 16837 ~ Absender: Variable
16:20:02 | 23728 | DEBUG | ScriptEngine | Skriptausführung - Ereignis: 59278 ~ Absender: Variable
16:20:02 | 23728 | DEBUG | ScriptEngine | Skript ausgeführt - Ereignis: 59278 ~ Absender: Variable
16:20:02 | 32612 | DEBUG | ScriptEngine | Skriptausführung - Ereignis: 21334 ~ Absender: TimerEvent
16:20:02 | 32612 | DEBUG | ScriptEngine | Skript ausgeführt - Ereignis: 21334 ~ Absender: TimerEvent
16:20:02 | 23728 | DEBUG | ScriptEngine | Skriptausführung - Ereignis: 53710 ~ Absender: Variable
16:20:02 | 23728 | DEBUG | ScriptEngine | Skript ausgeführt - Ereignis: 53710 ~ Absender: Variable
16:20:02 | 33028 | DEBUG | ScriptEngine | Skriptausführung: 33028 ~ Absender: RunScript
16:20:02 | 00000 | CUSTOM | 33028 | Heizung - FBH Wohnzimmer Aus
16:20:02 | 33028 | DEBUG | ScriptEngine | Skript ausgeführt: 33028 ~ Absender: RunScript
16:20:02 | 00000 | DEBUG | ScriptEngine | Skriptausführung (Text) - Länge: 38 ~ Absender: TimerEvent
16:21:04 | 00000 | MESSAGE | ScriptEngine | Zu viele gleichzeitige Skripte. Verwerfe Ausführung…
16:21:04 | 00000 | MESSAGE | ScriptEngine | Zu viele gleichzeitige Skripte. Verwerfe Ausführung…
16:21:05 | 00000 | MESSAGE | ScriptEngine | Zu viele gleichzeitige Skripte. Verwerfe Ausführung…
16:21:05 | 00000 | MESSAGE | ScriptEngine | Zu viele gleichzeitige Skripte. Verwerfe Ausführung…
16:21:06 | 00000 | MESSAGE | ScriptEngine | Zu viele gleichzeitige Skripte. Verwerfe Ausführung…
16:21:10 | 00000 | MESSAGE | ScriptEngine | Zu viele gleichzeitige Skripte. Verwerfe Ausführung…
16:21:11 | 00000 | MESSAGE | ScriptEngine | Zu viele gleichzeitige Skripte. Verwerfe Ausführung…
16:21:16 | 00000 | MESSAGE | ScriptEngine | Zu viele gleichzeitige Skripte. Verwerfe Ausführung…

Gibt es noch einen Ort an dem ich sehen kann was zum Absturz führte?

Steht doch mehr oder weniger da, zu viele Skripte. Hast Du denn mal Expertenansicht PHP informationen geschaut wie viele Skripte laufen und vor allem was das für Skripte sind? Wenn der Rechner Luft hat, dann einfach unter Spezialschalter anzeigen die Anzahl des Threads hochstellen. Auf was ist das denn zur Zeit eingestellt bei Dir und auf welcher Maschine läuft IPS?

Hmmm … Ich habe schon Mal in der Expertenansicht geschaut und im Normalfall sind selten alle 10 threats aktiv. Ich habe irgendwie das Gefühl das sich eine quer legt und die threats blockiert und nicht mehr frei gibt? Somit wären mehr threats keine Lösung - auch müsste das housekeeping Langläufer killen und die habe ich nicht … Soweit ich weiß.

Ich habe das curl script in Verdacht aber es ist eben nur so einer …

Um den Verdacht zu prüfen könntest du die Aufrufe des Skriptes ja mal rausnehmen. Je nachdem, ob das System dann weiterhin crasht oder nicht, wissen wir, ob der Verdacht begründet war.

Und nochmal zum FHZ-Gerät: Der Fix ist mittlerweile auf dem Beta-Kanal verfügbar. Um den zu nutzen müsstest du den Update-Kanal auf „Beta“ ändern, falls er aktuell auf „Stable“ steht.
Der Fix löst allerdings nur das Symptom und verhindert bei fehlerhaften Nachrichten einen Absturz. Dennoch scheint dein System irgendwo fehlerhafte Nachrichten zu verschicken. Daher würde ich dir empfehlen, das noch einmal zu prüfen. Verschickt ein Skript oder ein Modul vielleicht problematische Nachrichten?

… und dann sind wir ab heute bei 87.5% aller Graphen…

Status bisher: mit den 75% der Graphen die die letzten 2 Wochen aktiv waren ist das „Phänomen“ nicht eingetreten…

stay tuned… am 23. Oktober gibts das nächste Update… es sei denn wir haben vorher einen „Treffer“.

homa

Hallo,

Ich bin seit meinem letzten Post auf dem beta-branch. Leider hatte ich schon wieder Abstürze, aber seltener.

Ich hab nochmal ein „back trace“ gemacht. Vielleicht hilft es ja.


Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x6bbff430 (LWP 3156)]
0x003e41a0 in ELVFHZ::ParseBuffer(unsigned int) ()
(gdb) bt
#0  0x003e41a0 in ELVFHZ::ParseBuffer(unsigned int) ()
#1  0x003e62ec in ELVFHZ::ReceiveData(IPSData const&) ()
#2  0x00a3313c in IPSFlowHandler::SendDataToChildren(unsigned short, IPSData const&) ()
#3  0x006834ac in IOSerialPort::completedReading(std::shared_ptr<std::array<char, 4096u> >, unsigned int, boost::system::error_code const&) ()
#4  0x00686f04 in boost::asio::detail::descriptor_read_op<boost::asio::mutable_buffers_1, boost::_bi::bind_t<void, boost::_mfi::mf3<void, IOSerialPort, std::shared_ptr<std::array<char, 4096u> >, unsigned int, boost::system::error_code const&>, boost::_bi::list4<boost::_bi::value<IOSerialPort*>, boost::_bi::value<std::shared_ptr<std::array<char, 4096u> > >, boost::arg<2> (*)(), boost::arg<1> (*)()> > >::do_complete(boost::asio::detail::task_io_service*, boost::asio::detail::task_io_service_operation*, boost::system::error_code const&, unsigned int) ()
#5  0x0035dde0 in boost::asio::detail::epoll_reactor::descriptor_state::do_complete(boost::asio::detail::task_io_service*, boost::asio::detail::task_io_service_operation*, boost::system::error_code const&, unsigned int) ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

viele Grüße
cervicor

Ich habe die problematische Funktion ParseBuffer noch einmal überprüft und finde keine Stelle, an der dieser Fehler fliegen könnte. Ist dein System auf dem aktuellen Stand? Kannst du mir mal deine Kernel-Version schicken?

hatte gestern 2 Abstürze… inner halb von ca. 2 Std.

Nach dem ersten hab ich die Hälfte der hinzugenommenen Graphen wieder deaktiviert… sprich ich hatte dann 81.25% der Graphen aktiv… und dann kam kurze Zeit später der 2. Absturz.

… und wieder halbiert… bin jetzt auf ca. 78% aktivierter Graphen.

ist muehsam… ich hoffte wir koennen irgend ein besseres Mittel einführen um das Problem zu fangen… sprich wenn ihr glaubt, daS es an den Graphen und deren updates im webfront liegen könnte, dann muessten sich doch entsprechende Teile des codes instrumentieren lassen…, oder ?

homa

Es tut mir leid, dass die Suche sich so aufwendig gestaltet. Leider haben wir bisher keine Idee woran es wirklich liegt. Ist ein einzelner Graph irgendwie problematisch und es gibt Probleme sobald dieser in der Gesamtmenge ist? Oder taucht das Problem auf sobald eine gewisse Anzahl an Graphen im WebFront eingebunden ist?

Ich habe auch das Problem, dass IP-Symcon ca. 1x am Tag unregelmäßig abschmiert.
Das ganze habe ich seit 4.3.

Magst du vielleicht auch das Debugging per GDB ausprobieren und uns einen Stracktrace geben?

paresy