Server crash / freeze (MariaDB?)

We've posted an important announcement regarding the current situation and the future of the game: Announcement

  • Server crash / freeze (MariaDB?)

    Nabend

    mein Server hat sich heute (zum ersten mal) aufgehangen und man konnte nicht mehr connecten:

    rwlogs.omega-zirkel.de/1553155824.log

    Gruß,
    Devidian
    Gamer aus Leidenschaft
    (Web) Entwickler aus Leidenschaft
    <3 Vater aus Leidenschaft <3
    (prio in aufsteigender Sortierung ;) )

    ~~~~~~~~~~~~~~~~~
    1. Entweder man macht etwas richtig oder lässt es bleiben!
    2. Egal wie lange etwas dauert, Hauptsache es wird fertig (irgendwann)
    ------------------------
    Discord: Devidian#1334
  • Der Log besagt, dass die Welt-Datenbank gelocked ist. Das trat scheinbar zur selben Zeit auf, als der "JavaCordBot" die Verbindung zu Discord verloren hat (das muss aber nicht unbedingt im Zusammenhang damit stehen). Verwendest du ein Plugin, welches auf die Welt-Datenbank zugreift? Dann kann so ein Phänomen zB passieren, wenn eine Transaktion noch ihren Lock auf die Datenbank hält (oder wenn bspw. zu viele ResultSets offen sind etc).
    Läuft der MySQL Server denn auf der selben Maschine? Ansonsten könnte es nämlich auch sein, dass ggf. die Verbindung zu diesem Server unterbrochen wurde.
  • Der JavaCordBot verliert öfter mal die Verbindung, stellt diese aber auch meistens wieder her. Ich bin mir nicht sicher ob ABM/GPS/PNB oder AreaProtection darauf zugreifen, ich glaube die die was speichern nutzen sqlite. Meine eigenen Plugins (auch das Discord Plugin) Nutzen jedenfalls die Welt Datenbank nicht.

    Ja der MySQL läuft auf der selben Maschine. MySQL ist schon langsam genug da muss der nicht noch woanders liegen :D
    Gamer aus Leidenschaft
    (Web) Entwickler aus Leidenschaft
    <3 Vater aus Leidenschaft <3
    (prio in aufsteigender Sortierung ;) )

    ~~~~~~~~~~~~~~~~~
    1. Entweder man macht etwas richtig oder lässt es bleiben!
    2. Egal wie lange etwas dauert, Hauptsache es wird fertig (irgendwann)
    ------------------------
    Discord: Devidian#1334
  • Die MySQL Meldungen sind sowohl gestern und heute nochmal aufgetreten:

    rwlogs.omega-zirkel.de/1553196366.log
    rwlogs.omega-zirkel.de/1553221808.log
    Gamer aus Leidenschaft
    (Web) Entwickler aus Leidenschaft
    <3 Vater aus Leidenschaft <3
    (prio in aufsteigender Sortierung ;) )

    ~~~~~~~~~~~~~~~~~
    1. Entweder man macht etwas richtig oder lässt es bleiben!
    2. Egal wie lange etwas dauert, Hauptsache es wird fertig (irgendwann)
    ------------------------
    Discord: Devidian#1334
  • Ich habe auch Mal in logs ein paar Tage zuvor gesehen und dort auch vereinzelt diese Meldungen gefunden.

    Aktuell hängt der Server wieder, bin aber gerade nicht Zuhause um ihn neu zu starten. Mein Neustart über Plugin hat nur teilweise geklappt. Das Plugin wurde beendet aber der Server läuft noch. Solange er hängt kann er vom System nicht neu gestartet werden.

    Ich habe auch die älteren logs auf meinen Webspace geladen, einfach die Adresse ohne Datei aufrufen dann sind dort alle.

    Werde später das aktuelle log noch synchronisieren mit dem Webspace und hier verlinken. Werde den Server Mal komplett neu starten, nicht nur den RW Server, Mal sehen ob das dann hilft.
    Gamer aus Leidenschaft
    (Web) Entwickler aus Leidenschaft
    <3 Vater aus Leidenschaft <3
    (prio in aufsteigender Sortierung ;) )

    ~~~~~~~~~~~~~~~~~
    1. Entweder man macht etwas richtig oder lässt es bleiben!
    2. Egal wie lange etwas dauert, Hauptsache es wird fertig (irgendwann)
    ------------------------
    Discord: Devidian#1334
  • rwlogs.omega-zirkel.de/1553308206.log

    Laut Aussagen von @Keiner-da ist der Server um 15:13 ausgestiegen, also hat ihn rausgeworfen und nicht mehr rein gelassen.
    Kurz vorher gabs wieder MySQL Meldungen. ca. 15:37 hab ich einen restart befehl per discord abgesetzt, der hat den server aber auch nicht beendet, kam aber wohl an weil ich die Rückmeldung bekam das das Plugin nun offline geht.

    PS: habe den Server übrigens dann von unterwegs per hoster-web-login neustarten lassen. Ist normal wieder hoch gefahren, mal sehen obs nochmal auftritt jetzt
    Gamer aus Leidenschaft
    (Web) Entwickler aus Leidenschaft
    <3 Vater aus Leidenschaft <3
    (prio in aufsteigender Sortierung ;) )

    ~~~~~~~~~~~~~~~~~
    1. Entweder man macht etwas richtig oder lässt es bleiben!
    2. Egal wie lange etwas dauert, Hauptsache es wird fertig (irgendwann)
    ------------------------
    Discord: Devidian#1334
  • Ich dachte erst es wäre jetzt ruhe aber im aktuellen log heute ab 2200+ wieder das selbe

    rwlogs.omega-zirkel.de/1553394608.log
    Gamer aus Leidenschaft
    (Web) Entwickler aus Leidenschaft
    <3 Vater aus Leidenschaft <3
    (prio in aufsteigender Sortierung ;) )

    ~~~~~~~~~~~~~~~~~
    1. Entweder man macht etwas richtig oder lässt es bleiben!
    2. Egal wie lange etwas dauert, Hauptsache es wird fertig (irgendwann)
    ------------------------
    Discord: Devidian#1334
  • Hmm... es ist schwer zu sagen, was genau dort los ist. Wenn die Probleme auftreten, scheinen gleichzeitig auch andere Probleme aufzutreten. Zum Beispiel scheinen im letzten Log die Locks genau dann aufzutreten, wenn offenbar mehrere Spieler die Verbindung verlieren und auch nicht mehr reconnecten können 8| Kann es möglicherweise sein, dass der Server-Prozess dann generell evtl. stark ausgelastet ist? Im Vorletzten Log tritt unmittelbar vorher auch die Meldung auf org.javacord.core.util.event.EventDispatcherBase Detected a a listener thread for Omega-Zirkel which is now running for over 10 seconds, wobei das während des Herunterfahrens ggf. nicht sehr aussagekräftig ist...

    Auf welchen Wert ist bei deinen MySQL Einstellungen innodb_lock_wait_timeout gesetzt? Standardmäßig steht er glaube irgendwo bei 50 (was schon ein recht hoher Wert ist), wenn er aber ggf. irgendwann mal auf bspw. 1 gesetzt wurde, könnte das gerade bei großen Transaktionen zu diesem Fehler führen.

    Wann traten die Probleme denn das erste Mal auf bzw. hast du unmittelbar zuvor irgendwas geändert (Plugin-Änderung, Linuxupdate, MySQL-Update, andere Programme installiert etc)? Handelt es sich um einen Rootserver oder um einen Gameserver?
  • Also ich fang mal von hinten an, es ist ein (V) Root Server, genauer gesagt der V80 hier: strato.de/server/linux-vserver/ Ich hab grundsätzlich noch nie einen Gameserver gemietet da ich auch mal andere dinge dort installieren möchte. System ist Debian 8 aktuell.

    Das entscheidende Ereignis war eigentlich der Patch, denn vorher hatte ich dieses Problem nie, zumindest ist es mir nicht so unter gekommen das sich der Server dabei aufhängt. Ich habe aber auch einige Anpassungen an meinen eigenen Plugins vorgenommen und das Map-Plugin installiert. Keines davon hat aber Zugriff auf die MySQL Datenbank. Und ich mach natürlich regelmäßig system updates... aber ob da jetzt genau eins war bevor ich das Problem zum ersten mal hatte kann ich nicht sagen.

    MySQL (MariaDB) Version ist mysql Ver 15.1 Distrib 10.0.38-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2

    Die javacord dispatcher meldung kommt üblicherweise wenn ich versuche den Server (während er schon hängt) über discord herunter zu fahren.

    Ich lade mir mal alle logs herunter (alle die auch rwlogs.omega-zirkel.de/ zu sehen sind) und gucke mir das mal genau an, da müßte ich auch die plugin updates nachvollziehen können.


    PS: MariaDB läuft in der Standard-Konfiguration, der wert innodb_lock_wait_timeout ist in keiner der configs überschrieben worden
    Gamer aus Leidenschaft
    (Web) Entwickler aus Leidenschaft
    <3 Vater aus Leidenschaft <3
    (prio in aufsteigender Sortierung ;) )

    ~~~~~~~~~~~~~~~~~
    1. Entweder man macht etwas richtig oder lässt es bleiben!
    2. Egal wie lange etwas dauert, Hauptsache es wird fertig (irgendwann)
    ------------------------
    Discord: Devidian#1334

    The post was edited 1 time, last by Devidian ().

  • Es tritt zum ersten mal am Montag 18.03.2019 um 17:58 Uhr auf. Scheinbar ist das letzte update dort mein GlobalIntercom gewesen von 0.9.0 auf 0.10.0. Allerdings habe ich dort nur change detection code eingebaut der schon lange in meinem anderen Plugin funktioniert.

    github.com/Devidian/oz_rw_plug…e5b90036bf98abf91d052dabc

    Und mein DiscordPlugin von 0.13.1 auf 0.13.2

    github.com/Devidian/oz_rw_plug…6771849234e8c06144de16b5b

    dort sehe ich auch nichts, das zu mysql Fehler führen soll hm.


    Ich habe vorhin mal das slowlog an gemacht und MySQL/RW Server neu gestartet:

    rwlogs.omega-zirkel.de/mysql-slow.log
    rwlogs.omega-zirkel.de/1553498927.log

    er ist relativ früh schon ausgestiegen. Der server hat überwiegend ein load average von 0.6 Punkten, selbst gestern wo 5 Spieler drauf waren war der kaum höher.

    Habe zum test mal alle (meine) Plugins entfernt.

    UPDATE:

    Auch ohne meine Plugins kommt der Fehler: (hatte sie restlos gelöscht aus dem plugin Verzeichnis)

    rwlogs.omega-zirkel.de/1553502794.log
    rwlogs.omega-zirkel.de/mysql-slow.log (aktualisiert)
    Gamer aus Leidenschaft
    (Web) Entwickler aus Leidenschaft
    <3 Vater aus Leidenschaft <3
    (prio in aufsteigender Sortierung ;) )

    ~~~~~~~~~~~~~~~~~
    1. Entweder man macht etwas richtig oder lässt es bleiben!
    2. Egal wie lange etwas dauert, Hauptsache es wird fertig (irgendwann)
    ------------------------
    Discord: Devidian#1334

    The post was edited 5 times, last by Devidian: Testergebnis ohne Plugins ().

  • Danke für den neuen Log! Vor allem auch danke für den slow-query-Log, der ist tatsächlich recht aufschlussreich: Hier fällt auf, dass zwar die SELECTs ziemlich schnell sind, aber (wenn ich das richtig sehe) sämtliche UPDATEs extrem lange brauchen =O Also mehrere Sekunden bis hin zu einer Minute. Selbst das erste UPDATE Statement, welches schon recht früh auftritt, braucht 13 Sekunden. Manche der UPDATE-Statements sind zwar schwer zu beurteilen, weil die auch Binary-Daten enthalten, aber selbst bei so ganz simplen Statements wie UPDATE WorldInfos SET `Key` = 'Time', `Value` = '19.4.12 13:3:0.81009114' WHERE `Key` = 'Time'; sind sage und schreibe 35 Sekunden vergangen, etwas später sogar teilweise über 60 Sekunden und gegen Ende auch 111 Sekunden (und dabei ist die WorldInfos Tabelle ja winzig mit nur einer handvoll Einträgen) 8| Früher oder später steigt dadurch auch die Lock-Time, bis hin zum Timeout.

    Wurde die Datenbank mit dem neuen WorldConverter von SQLite zu MySQL übertragen, oder lief der RW Server schon vorher mit MySQL / MariaDB?

    Es sieht so aus, als würde möglicherweise irgendwas auf dem Server Amok laufen und die Datenbank extrem ausbremsen :huh: Oder vielleicht sind irgendwelche MySQL Einstellungen verstellt (sodass ihm wenig RAM zur Verfügung steht, oder er nur einen sehr kleinen Cache zur Verfügung hat o.ä). Leider ist das schwer zu sagen, was genau dort los ist.

    Am Spiel hat sich mit den letzten Updates eigentlich nichts geändert, das irgendwie einen direkten Einfluss auf die SQL Abfragen haben könnte ?(
  • Also ich hab den Server von Anfang an auf MySQL laufen gehabt, habe es extra dafür installiert :D privat nutze ich nur noch MongoDB da es einfach performanter ist - und diverse andere Vorteile bringt.

    Wie gesagt habe ich an den MySQL Einstellungen nichts geändert außer das ich das slowlog jetzt an habe. Und es gibt kein anderes Programm das darauf zugreift...
    Gamer aus Leidenschaft
    (Web) Entwickler aus Leidenschaft
    <3 Vater aus Leidenschaft <3
    (prio in aufsteigender Sortierung ;) )

    ~~~~~~~~~~~~~~~~~
    1. Entweder man macht etwas richtig oder lässt es bleiben!
    2. Egal wie lange etwas dauert, Hauptsache es wird fertig (irgendwann)
    ------------------------
    Discord: Devidian#1334
  • cdn.discordapp.com/attachments…3019581450/screenshot.jpg

    MaxthonSnap20190325173724.png

    Hier wieder ein Vorfall, hat diesmal sogar ingame eine Meldung abgegeben. Auf dem Server zur selben Zeit nix los.

    Das dürfte das log dazu sein: rwlogs.omega-zirkel.de/1553530222.log
    Gamer aus Leidenschaft
    (Web) Entwickler aus Leidenschaft
    <3 Vater aus Leidenschaft <3
    (prio in aufsteigender Sortierung ;) )

    ~~~~~~~~~~~~~~~~~
    1. Entweder man macht etwas richtig oder lässt es bleiben!
    2. Egal wie lange etwas dauert, Hauptsache es wird fertig (irgendwann)
    ------------------------
    Discord: Devidian#1334
  • Devidian wrote:

    Hier wieder ein Vorfall, hat diesmal sogar ingame eine Meldung abgegeben. Auf dem Server zur selben Zeit nix los.
    Dieser Fehler bzw. das Phänomen hängt nicht mit der Spielerzahl zusammen, da selbst die einfachsten, kleinen SQL UPDATEs (zB bei den WorldInfos, diese Tabelle hat gerade mal 3 Spalten und 17 Zeilen, als eine winzig kleine Tabelle) schon extremst langsam sind (lt. slow query log) :huh: Das ist wirklich sehr unnormal...

    Am Spiel bzw. am Update sollte das eigentlich nicht liegen, ich kann das natürlich nicht zu 100% ausschließen, aber ich konnte eigentlich nichts ungewöhnliches finden (zumal du ja sagst, dass der Fehler erst letzten Montag auftrat, d.h. es könnte wenn an einem der Hotfixes liegen, aber das ist eigentlich noch unwahrscheinlicher) 8| Es gibt noch mehrere Server, die MySQL verwenden, es hatte sich aber noch niemand mit einer ähnlichen Problematik gemeldet (was aber nichts heißen muss).

    Die absolute Notlösung wäre, auf SQLite umzusteigen (wobei diese Lösung natürlich eher suboptimal ist) :/
  • Das einzige was ich mir noch vorstellen kann das von meinem Server kommt wäre das stündliche backup der weltdaten meiner 7 days 2 die instanz, ich hab das mal deaktiviert - da spielt gerade eh keiner aktiv. Ich berichte dann... Könnte theoretisch für den moment zu einer hohen waitIO führen auf der platte ... aber dann müßte man evtl nur mysql irgendwie anders einstellen das er da keine Probleme macht - ich hab mich nur noch nie wirklich mit den mysql Einstellungen tiefgehend befasst auch wenn ich über 10 Jahre nur mit mysql gearbeitet habe...
    Gamer aus Leidenschaft
    (Web) Entwickler aus Leidenschaft
    <3 Vater aus Leidenschaft <3
    (prio in aufsteigender Sortierung ;) )

    ~~~~~~~~~~~~~~~~~
    1. Entweder man macht etwas richtig oder lässt es bleiben!
    2. Egal wie lange etwas dauert, Hauptsache es wird fertig (irgendwann)
    ------------------------
    Discord: Devidian#1334
  • Ich glaube es waren tatsächlich die Backups. Die Backups liefen zwar mit rsync und hardlinks und haben nur knapp über 300MB im Moment, jedoch war im backup Verzeichnis schon >2k unterordner drin (je stunde ein Ordner). Habe die Backups mal alle bereinigt und jetzt nicht mehr ganz so oft laufen lassen.

    Finde ich jedoch trotzdem krass das rsync dann mysql wait lock verursacht :huh: . Wenn ich da an unsere MongoDB Instanzen denke auf der Arbeit, die haben schon mehr IO wait gehabt und trotzdem im ms bereich ausgeliefert, selbst bei Millionen Datensätzen...

    Ganz sicher bin ich mir zwar noch nicht aber die Vermutung liegt nah.
    Gamer aus Leidenschaft
    (Web) Entwickler aus Leidenschaft
    <3 Vater aus Leidenschaft <3
    (prio in aufsteigender Sortierung ;) )

    ~~~~~~~~~~~~~~~~~
    1. Entweder man macht etwas richtig oder lässt es bleiben!
    2. Egal wie lange etwas dauert, Hauptsache es wird fertig (irgendwann)
    ------------------------
    Discord: Devidian#1334