Steam Client Timeout auf Server

Ich habe die logs mit docker compose logs --since ... > umgeleitet um auch die start und end echos vom entrypoint.sh script mit zu haben.

Das angehängte log hat 3 Sessions, eine kurze eine lange, beide mit SIGSEGV und eine "normale" danach die wegen fehlendem freien port beendet wurde.

An diesem log sieht man sehr schön das es komplett random erscheint wann der prozess abschmiert.

Ich weiss nicht obs relevant ist aber eben habe ich eine Blaupause machen wollen und genau dann ist er abgeschmiert. Ist zumindest mal was anderes.

Gestern wars ganz schlimm, gefühlt gibt es mehr SIGSEGV seit ich das extra JNI logging aktiviert habe. Ich habe das 26MB log von gestern gesplittet und alle sessions mit SIGSEGV lade ich hier mal hoch. Auffällig war nur das ein Spieler auch sagte er habe vorher mit einer Blaupause hantiert direkt vor dem crash.

session6 war übrigens mit einer neuen Discord Plugin version, ich habe bei dem Plugin die veraltete JavaCord lib gegen JDA ausgetauscht in der Hoffnung auf Besserung aber ich war nur kurz da und hab ein paar Steine gehauen als er wieder abgeschmiert ist.

Vielen Dank für die neuen Logs! Die Crashes treten an der selben Stelle auf, da liegt also offensichtlich die selbe Ursache zugrunde... ich vermute stark es hängt mit der Ausgabe Create new JNIEnv zusammen, was einfach auffallend häufig vorkommt. Verdächtig ist, dass es meist kurz nach der Ausgabe [Java] [OZ.AdminUtils] chunk xx xx updated kommt. AdminUtils erzeugt aber keine neuen Threads, oder? Welche Methoden ruft diese Stelle auf? Ist das evtl. die Screenshot Funktion? Kannst du mir diesen Code sonst evtl. mal senden (gerne auch per PN)?

Das mit den Blueprints könnte reiner Zufall sein (oder lauscht du zufällig auf die entsprechenden Events und machst da etwas spezielles)?

Wenn im Plugin sonst aber wirklich keine neuen Threads erstellt werden, vermute ich, dass es wohl irgendwie mit den Callbacks zusammenhängt, dass immer neue JNIEnvs erzeugt werden. Ich gehe auch stark davon aus, dass das für die Crashes verantwortlich ist, denn JNIEnvs werden nicht automatisch aufgeräumt oder detached. Sie werden aber trotzdem vom GC geprüft. Wenn sie nun von OS-Seite sterben und implizit aufgeräumt werden, könnte das unter Umständen den Crash erklären (da JNI weiterhin die Referenz hält).

Eine potenzielle Lösung für das Problem: Einen anderen Garbage Collector verwenden. Das Concurrent-Marking verursacht das Problem, d.h. ein anderer GC ohne SATB-Buffer würde wahrscheinlich keinen Crash verursachen. Du könntest testweise die server.properties Datei öffnen und unter Plugins_VMOptions mal -XX:+UseParallelGC eintragen, also:

Plugins_VMOptions=-XX:+UseParallelGC

Das sollte einen anderen GC verwenden, der keine SATB Buffer benutzt. Ist natürlich keine richtige Lösung für das Problem (da es möglicherweise etwas die Performance schmälert), wäre aber testweise mal interessant zu wissen, ob die Crashes dann weiterhin auftreten. Falls es dann sauber läuft, würde es höchstwahrscheinlich wirklich an obiger Theorie liegen.

AdminUtils aktualisiert die chunk Oberflächen für die map, allerdings habe ich das erst kürzlich aktiviert, die crashes gab es schon vorher. Ich kann es aber Zeitweise mal wieder deaktivieren und dann noch mal logs generieren.

Die KI hatte mir auch vorgeschlagen UseParallelGC oder UseSerialGC zu verwenden, aktuell hab ich letzteres aktiviert seit 9:48 heute. Bisher gab es noch keinen crash. Sollte es einen weiteren geben werde ich die Mapping Funktion aus AdminUtils deaktivieren.

Bisher habe ich noch kein Plugin das auf blueprints lauscht.

Die chunk x z Ausgabe findet hier statt: https://github.com/Devidian/rw…dMapChunkCapture.java#L30

Hier mal aus der aktuellen log session, die noch nicht abgestürzt ist:

[Java] [OZ.ThreadDiagnostics] Thread summary: current=59, peak=69, totalStarted=429, names={Cleaner-0=1, Common-Cleaner=1, FileSystemWatchService=1, Finalizer=1, JDA Gateway-Worker 1=1, JDA MainWS-ReadThread=1, JDA MainWS-WriteThread=1, JDA RateLimit-Elastic-Worker 2=1, JDA RateLimit-Scheduler-Worker 1=1, JDA RateLimit-Scheduler-Worker 2=1, Notification Thread=1, OZ-ThreadDiagnostics=1, OZAdminUtils-MapSource=1, OZDiscordConnect-ActivityTimer=1, OZDiscordConnect-RestartTimer=1, OZDiscordConnect-Transport=1, PluginFileWatcher-Thread=1, ReadingThread=1, Reference Handler=1, Signal Dispatcher=1, Thread-26=1, Thread-27=1, Thread-28=1, Thread-29=1, Thread-30=1, Thread-31=1, Thread-37=1, Thread-38=1, Thread-39=1, Thread-40=1, Thread-41=1, Thread-42=1, Thread-43=1, Thread-44=1, Thread-50=1, Thread-51=1, Thread-52=1, Thread-53=1, Thread-8=1, WebSocket-Reconnect=1, WritingThread=1, httpclient-dispatch-1=1, httpclient-dispatch-10=1, httpclient-dispatch-11=1, httpclient-dispatch-12=1, httpclient-dispatch-13=1, httpclient-dispatch-14=1, httpclient-dispatch-15=1, httpclient-dispatch-16=1, httpclient-dispatch-2=1, httpclient-dispatch-3=1, httpclient-dispatch-4=1, httpclient-dispatch-5=1, httpclient-dispatch-6=1, httpclient-dispatch-7=1, httpclient-dispatch-8=1, httpclient-dispatch-9=1, httpclient-main-1=1, main=1}

Die Session lief bis zum geplanten Neustart einwandfrei durch und es waren einige Spieler aktiv

[Java] [OZ.ThreadDiagnostics] Thread summary: current=65, peak=69, totalStarted=626, names={Cleaner-0=1, Common-Cleaner=1, FileSystemWatchService=1, Finalizer=1, ForkJoinPool.commonPool-worker-80=1, JDA Gateway-Worker 1=1, JDA MainWS-ReadThread=1, JDA MainWS-WriteThread=1, JDA RateLimit-Elastic-Worker 2=1, JDA RateLimit-Scheduler-Worker 1=1, JDA RateLimit-Scheduler-Worker 2=1, Notification Thread=1, OZ-ThreadDiagnostics=1, OZAdminUtils-MapSource=1, OZDiscordConnect-ActivityTimer=1, OZDiscordConnect-RestartTimer=1, OZDiscordConnect-Transport=1, OkHttp TaskRunner=4, Okio Watchdog=1, PluginFileWatcher-Thread=1, ReadingThread=1, Reference Handler=1, Signal Dispatcher=1, Thread-26=1, Thread-27=1, Thread-28=1, Thread-29=1, Thread-30=1, Thread-31=1, Thread-37=1, Thread-38=1, Thread-39=1, Thread-40=1, Thread-41=1, Thread-42=1, Thread-43=1, Thread-44=1, Thread-50=1, Thread-51=1, Thread-52=1, Thread-53=1, Thread-8=1, WebSocket-Reconnect=1, WritingThread=1, httpclient-dispatch-1=1, httpclient-dispatch-10=1, httpclient-dispatch-11=1, httpclient-dispatch-12=1, httpclient-dispatch-13=1, httpclient-dispatch-14=1, httpclient-dispatch-15=1, httpclient-dispatch-16=1, httpclient-dispatch-2=1, httpclient-dispatch-3=1, httpclient-dispatch-4=1, httpclient-dispatch-5=1, httpclient-dispatch-6=1, httpclient-dispatch-7=1, httpclient-dispatch-8=1, httpclient-dispatch-9=1, httpclient-main-1=1, main=1}
...
Invoke shutdown via command...
[WARNING] [17:02:22] Exit (0)
[WARNING] [17:02:22] Q U I T   R I S I N G   W O R L D   S E R V E R
Stopping Webserver...
STEAM SERVER SHUTDOWN
...
JNI: DESTROY JAVA VM
Create new JNIEnv  (handle: 93843685619264, thread: 95460)
[Java] [OZLogger] Terminating Log4j framework globally.
NativeMemoryManager: Free 30855 memory pointers (305333707 B)...
[END]

interessant ist hier das er shutdown macht aber danach 5 mal neustarten muss weil er das problem mit dem port hat. Du hattest mal gesagt das man in den settings Server_RestartEnabled=False verwenden soll, aber geholfen hat es nicht

Da kommt dann immer das hier:

Create Public Webserver IP: 0.0.0.0 Port: 4254
Add Prefix: /
Add Prefix: /info
Add Prefix: /playerlist
Add Prefix: /images/header
Add Prefix: /game/maptile
Add Prefix: /game/image
Add Prefix: /game/asset
Add Prefix: /game/chunkmultirequest
[ERROR] [17:04:05]  !!! UNCAUGHT EXCEPTION !!! 
    UnityEngine.DebugLogHandler:Internal_Log(LogType, LogOption, String, Object)
    RisingWorld.Server.Main:HandleError(Exception)
    RisingWorld.Common.JIWApplication:Update()


[ERROR] SocketException: Address already in use
    System.Net.Sockets.Socket.Bind (System.Net.EndPoint localEP) (at <00000000000000000000000000000000>:0)
    NetCoreServer.TcpServer.Start () (at <00000000000000000000000000000000>:0)
    RisingWorld.Server.Main.InitWebserver () (at <00000000000000000000000000000000>:0)
    RisingWorld.Server.Main.OnPostInitialize () (at <00000000000000000000000000000000>:0)
    RisingWorld.Common.JIWApplication.Update () (at <00000000000000000000000000000000>:0)
    ExceptionExtensions:PrintStackTrace(Exception)
    RisingWorld.Server.Main:HandleError(Exception)
    RisingWorld.Common.JIWApplication:Update()


[WARNING] [17:04:05] Exit (1)
[WARNING] [17:04:05] Q U I T   R I S I N G   W O R L D   S E R V E R
Stopping Webserver...
STEAM SERVER SHUTDOWN

Und im Discord sieht das so aus:

kann ich den Xms wert eigentlich auch über eine server property steuern oder muss ich den mit Plugins_VMOptions überschreiben? Die KI meint der Wert wäre etwas niedrig gewählt

PS: Die Nachtsession lief auch durch. Wenn der heutige Tag auch ohne SIGSEGV oder anderem Absturz läuft schalte ich morgen früh mal auf ParallelGC

warum bekommst du hs_err_pid dateien aber ich nicht 😢😅

Na aber die habe ich ja auch auf true

Shutdown macht er ja, trotzdem die Wiederholung. Allerdings ist mir aufgefallen das er auf dem Dev Server keine Wiederholung macht wenn in der Session kein Spieler online war

PS bisher stabil mit anderem gc

Quote from Devidian

Die chunk x z Ausgabe findet hier statt: https://github.com/Devidian/rw…dMapChunkCapture.java#L30

Oh, vielen Dank für den Link! Auf dem ersten Blick sehe ich tatsächlich keine Threads, die da erzeugt werden.. auch der native Code, der dort aufgerufen wird, läuft komplett synchron, also auch hier keine Extrathreads o.ä

Habe noch etwas tiefer gegraben und denke nicht, dass die AdminUtils relevant sind... die häufigen JNIEnv-Ausgaben bzw. die scheinbar häufigen Threads scheinen stattdessen 2 Ursachen zu haben:

1. DiscordConnect bzw. JDA: Die Umstellung von Javacord auf JDA ist auf jeden Fall hilfreich und führt auch zu deutlich weniger Threads, aber in ForkJoinPool und OkHttp sind weiterhin Threads, die sterben bzw. kurzlebig sind.

2. Aber auch der Asset-Download des Servers, was (um das Netzwerksystem bei großen Daten nicht zu überlasten) über den Webserver läuft. Das ist tatsächlich die eine Stelle im Server (genau genommen der darunterliegende HttpListener), die ebenfalls Threads verwendet, die sterben.

Was genau die Crashes verursacht ist schwer zu sagen, aufgrund der Häufigket würde ich zu 1 tendieren, aber sowohl 1 als auch 2 haben das Potenzial dazu.

Nichtsdestotrotz ist das so oder so ein Bug in der API. D.h. das Plugin macht definitiv nichts "falsch", denn auch mit sterbenden bzw. kurzlebigen Threads muss die API umgehen können

Quote from Devidian

Die Session lief bis zum geplanten Neustart einwandfrei durch und es waren einige Spieler aktiv

Freut mich, wenn der andere GC geholfen hat! Das würde die ganze obige Theorie mit der SATB Queue und den JNIEnvs tatsächlich bestätigen. Ich schaue aber trotzdem weiter nach einer robusten Lösung, damit die API mit kurzlebigen Threads umgehen kann. Und Punkt 2 oben ist ohnehin relativ einfach zu beheben (auch wenn ich nicht glaube, dass das die häufigen Crashes in diesem Fall verursacht, ist es trotzdem ein potenzieller Kandidat für solche Crashes)^^

Quote from Devidian

interessant ist hier das er shutdown macht aber danach 5 mal neustarten muss weil er das problem mit dem port hat. Du hattest mal gesagt das man in den settings Server_RestartEnabled=False verwenden soll, aber geholfen hat es nicht

Hast du evtl. einen Log vom Start (wegen dem blockierten Port)?

Quote from SonoBionda

komisch - seit gestern erhalte ich wieder hs-err-pid Dateien und deswegen hab ich heute direkt mal auf den ParallelGC gewechselt (nicht, dass das wieder zur Gewohnheit wird)

Danke für die beiden hs_err_pid Dateien! Traten denn mit dem ParallelGC auch weiterhin Crashes auf? Rein auf den ersten Blick scheinen die Crashes tatsächlich die gleiche oder zumindest eine ähnliche Ursache zu haben: Hier scheint es auch kurzlebige Threads zu geben (konnte aber keinen Anhaltspunkt zu DiscordConnect oder OkHttp o.ä finden, daher wohl eine andere Quelle, die die Threads erzeugt). Sieht nach Java Threads aus, kann aber nicht ausschließen, dass es vll auch vom AssetDownload bzw. Webserver kommt.

In jedem Fall müsste aber der ParallelGC auch hier helfen.

Bitte sage mir nicht, dass es mit ParallelGC weiterhin crasht, denn dann würde das Kartenhaus schnell in sich zusammenfallen (in dem Fall aber bitte gerne eine neue hs_err_pid)

Quote from Devidian

warum bekommst du hs_err_pid dateien aber ich nicht 😢😅

Ich könnte mir vorstellen, dass es evtl. mit Linux und Docker zusammenhängt Unter Linux wird der Crash anders behandelt und lt. Log wird das auch tatsächlich an Unity weitergegeben bzw. von Unity ausgegeben. Unter Windows behandelt die JVM die Crashes anders.

Wahrscheinlich könnte aber auch Docker eine Rolle spielen... vll könnte es helfen, einen festen Pfad für die hs_err_pid Datei zu vergeben. Das kann mit der JVM Option -XX:ErrorFile= gemacht werden (zB -XX:ErrorFile=/Logs/hs_err_pid_%p.log). Du kannst in der server.properties mehrere JVM Options mit Semikolon getrennt angeben. KA ob das wirklich hilft...

Hmm da durch meine Shop und Marketplace viele assets aus dem spiel geladen werden vielleicht? (also Case 2) Discord Connect lief ja schon länger ohne Probleme vorher, klar kann das ein zusätzlicher Faktor sein aber zuletzt kamen Shop und MArketplace dazu, die haben eigentlich keine Threads, höchstens ein paar Timer im Shop für den refill, aber der dürfte planmäßig nur einmal die Stunde laufen. Bin mir gerade nicht sicher ob er da einen eigenen Thread für macht. Laut KI jedenfalls nicht.

Das mit dem ErrorFile kann ich mal probieren aber dann muss ich wieder umstellen, sonst kommt gar kein error mehr

Klar ich hab ja noch die anderen logs eigentlich dürften die relativ identisch sein habe aber trotzdem mal 4 hinzugefügt.

Quote from Devidian

Hmm da durch meine Shop und Marketplace viele assets aus dem spiel geladen werden vielleicht? (also Case 2) Discord Connect lief ja schon länger ohne Probleme vorher, klar kann das ein zusätzlicher Faktor sein aber zuletzt kamen Shop und MArketplace dazu, die haben eigentlich keine Threads, höchstens ein paar Timer im Shop für den refill, aber der dürfte planmäßig nur einmal die Stunde laufen. Bin mir gerade nicht sicher ob er da einen eigenen Thread für macht. Laut KI jedenfalls nicht.

Also wenn die Assets aus dem Spiel geladen werden, dann werden da eigentlich keine Daten ausgetauscht, zumindest nicht über den Webserver Die sollten diesen Bug also eigentlich nicht triggern... nur normale Assets, die auch tatsächlich vom Server heruntergeladen werden (aber auch hier ist das eher bei neuen Spieler relevant, da nach dem Download die Assets lokal gecached werden).

Timer verwenden auch keine Threads, auch die Plugin-Funktionen executeDelayed() oder enqueue() verwenden keine Threads.

Aber ich werde mit der nächsten Gelegenheit eine Änderung einbauen, mit welcher die "Create new JNIEnv" (zumindest bei aktivierten Debug-Optionen) zusätzlich auch einen Stacktrace ausgibt (für C# und Java), dann würde man sofort sehen, woher die Threads tatsächlich kommen Aber idealerweise ist der Bug mit den leakenden JNIEnvs (was letztenendes den SATB-Crash verursacht) bis zum nächsten Update auch sowieso behoben

Quote from Devidian

kann ich den Xms wert eigentlich auch über eine server property steuern oder muss ich den mit Plugins_VMOptions überschreiben? Die KI meint der Wert wäre etwas niedrig gewählt

Sorry, ich habe die Frage oben übersehen Aber ja, auch dafür gibts eine Einstellung, leider aber versteckt. Du musst dafür Plugins_InitialMemory zur server.properties hinzufügen, also zB Plugins_InitialMemory=512 für 512 MB Startmemory. Standardmäßig ist das nur auf 32 gesetzt (was wir vll tatsächlich etwas anheben könnten)

Danke für die Logs übrigens! Ist das mit dem Port immer so? Also auch wenn du nach einem Start zB direkt neustartest? Oder nur gelegentlich?

Wenn in der Session keiner online war macht er einen Neustart und gut ist, wenn jemand online war - auch wenn der schon länger offline war wie man hier sieht - gibt es immer das port problem. Vielleicht ist es auch ein docker problem, da bin ich überfragt.