How to diagnose server 'hangs'

[Alonzo]

Hey all,

 

I've posted in the past about my dserver apparently getting 'stuck' somehow. It's still happening, and it's actually happening across all of my maps, regardless of player load. I thought it was high load situations that cause it, but apparently it's just kind of random. I have a server control script (posted in another thread) that randomly chooses a map, rewrites the SDS config file, runs dserver with "ShutdownLoads = 1" set to run just a single map, and then monitors the server and waits for it to finish. I've now added logging to the script and got the following warnings this week:

 

2019/07/02 21:16:41 dserver-controller.pl:237    WARN    Map time exceeded by more than one minute, map was Dogfight\Alonzo\Battle_for_Kalinin\Battle-for-Kalinin-Aug-1944a-ALT.
2019/07/03 02:18:29 dserver-controller.pl:237    WARN    Map time exceeded by more than one minute, map was Dogfight\Alonzo\Operation_Frantic\Operation-Frantic-June-1944a-ALT.
2019/07/03 17:20:30 dserver-controller.pl:237    WARN    Map time exceeded by more than one minute, map was Dogfight\Alonzo\Stalingrad_Scramble\Stalingrad-Scramble-Feb-1945.
2019/07/04 05:51:43 dserver-controller.pl:237    WARN    Map time exceeded by more than one minute, map was Dogfight\Alonzo\Operation_Eisenhammer\Operation-Eisenhammer-Feb-1945-ALT.
2019/07/04 15:52:40 dserver-controller.pl:237    WARN    Map time exceeded by more than one minute, map was Dogfight\Alonzo\Operation_Paravane\Operation-Paravane-Sep-1944.
2019/07/04 18:24:01 dserver-controller.pl:237    WARN    Map time exceeded by more than one minute, map was Dogfight\Alonzo\Operation_Frantic\Operation-Frantic-June-1944a.
2019/07/04 20:55:20 dserver-controller.pl:237    WARN    Map time exceeded by more than one minute, map was Dogfight\Alonzo\Crimean_Offensive\Crimean-Offensive-Apr-1944a.
2019/07/05 09:26:16 dserver-controller.pl:237    WARN    Map time exceeded by more than one minute, map was Dogfight\Alonzo\Operation_Eisenhammer\Operation-Eisenhammer-Feb-1945.
2019/07/05 14:28:00 dserver-controller.pl:237    WARN    Map time exceeded by more than one minute, map was Dogfight\Alonzo\Stalingrad_Scramble\Stalingrad-Scramble-Feb-1945.

(it might seem like one minute isn't much, but my server is on fast hardware and this generally indicates that the shutdown failed and the server is about to sit there indefinitely)

 

I got to this point because running dserver with multiple missions configured, I would get situations where the server thought it had rolled to a new map, but no players were able to join. My hunch is that this is caused by the same problem as the "shutdown hang" problem. 

 

Is anyone familiar with how I might debug this problem? Is there a way I can attach a debugger to the running dserver when it is in the 'hung' state? I used to be a competent programmer so I can probably find my way around a debugger, but I pretty much have no clue what language is being used for dserver or whether I can even attach to it. Anyone know?

 

Alternatively, has anyone seen this kind of problem? Was it caused by something in particular that I can avoid? My maps all feature common elements copied and remixed amongst the maps, so it could be a problem there. All the targets use Jim's Target Defence Switch to try to optimize which AI units are active, so they are running quite a few Check Zones across each map, as well as (over the course of a complete map run) a fair number of AI activate/deactivates.

[BubiHUN]

when you put down a waypoint, and doesnt connect it to anything, run Tools ->Start Integrity Check. It will bring up a window the limitations what you can work with, and the "unconnected" waypoint. 
When you make a mission, and what you put down, vehicles, buildings, etc above those limits what it is described in that little window, it's all about server pc performance.

[Habu]

Alonzo, if you think that the mission is faulty, i can try to host one on my server to see if i have the same problem.

 

 

[Alonzo]

7 hours ago, -[HRAF]BubiHUN said:

when you put down a waypoint, and doesnt connect it to anything, run Tools ->Start Integrity Check. It will bring up a window the limitations what you can work with, and the "unconnected" waypoint. 
When you make a mission, and what you put down, vehicles, buildings, etc above those limits what it is described in that little window, it's all about server pc performance.

 

Ooh. I could never get the integrity check to run before. Thanks! Here's the output for the recent Stalingrad Scramble map:

Object(13078:Trigger Waypoint) >> Waypoint must have at least one object connected!
Max buildings with entity number exceeded! max: 10, actual: 774
Max flags with entity number exceeded! max: 8, actual: 22
Max vehicles with entity number exceeded! max: 40, actual: 301
Max planes with entity number exceeded! max: 20, actual: 29
Max effects with entity number exceeded! max: 12, actual: 175
Max total entity number exceeded! max: 80, actual: 1312

Do any of these seem too much for a fast server? It's an 8600K at 4.6ghz with fast RAM. Tick times seem good (usually < 10ms).

 

7 hours ago, Habu said:

Alonzo, if you think that the mission is faulty, i can try to host one on my server to see if i have the same problem.

 

Thanks Habu! Here is a link to Battle for Kalinin. The mission should finish after 2.5 hours depending on which side has destroyed more targets. But you could set the timer shorter if you like, by looking at the "GLOBAL Logic and Timing" group. Everything is chained from the central "Mission Begin" MCU.

[BubiHUN]

4 minutes ago, Alonzo said:

Do any of these seem too much for a fast server? It's an 8600K at 4.6ghz with fast RAM. Tick times seem good (usually < 10ms).

Yes, as the integrity check says. THe limtations are pretty low.

[Habu]

Do not take too seriously the information provide by the limitation. It's just an indication and can be truly false. Keep in mind that limitation were introduce during the development of Rise of flight, and our PC are not the same. Most of my mission are over the limitation with no problem.

 

Another thing about the indication, is that they could be false.

You can have 40 planes in the mission, but only have 5 in game and other will spawn later. But in the indication you will be over the limitation. It's up to you to know your hardware and test the limit of your hardware. And the limit of the hardware of one personn is not the same of another one if the hardware is different.

 

Alonzo, i'll try to test your mission asap, but dev gave us some works. ?

 

How many players play that mission at the same time ?

 

 

Edited July 6, 2019 by Habu

[Alonzo]

10 hours ago, Habu said:

Do not take too seriously the information provide by the limitation. It's just an indication and can be truly false. Keep in mind that limitation were introduce during the development of Rise of flight, and our PC are not the same. Most of my mission are over the limitation with no problem.

 

Another thing about the indication, is that they could be false.

You can have 40 planes in the mission, but only have 5 in game and other will spawn later. But in the indication you will be over the limitation. It's up to you to know your hardware and test the limit of your hardware. And the limit of the hardware of one personn is not the same of another one if the hardware is different.

 

Alonzo, i'll try to test your mission asap, but dev gave us some works. ?

 

How many players play that mission at the same time ?

 

We sometimes have upwards of 60 players. The current server limit is 64. With 60+ players, we see tick times around 12-15ms. With 30 players, only 10ms. I have taken care to use activation logic to only have a smaller number of units active, based on player location. It seems like the maps can 'hang' even with a small number of players, like 4-6, which is why I am thinking maybe I have done something weird in the mission creation. It doesn't seem to be server load related.

[Alonzo]

In case anyone is interested, I found this in the most recent dserver log. It looks like a normal shutdown, right?

 

03:04:43	Remote Console service started on 127.0.0.1 port 8991

03:04:43	=====	DeathMatch mode	=====
03:04:43	=====	Dedicated server	=====
03:04:43	Brief info:
03:04:43		Max clients = 65
03:04:43		TCP: 28000, UDP: 28000, Downloader: 28100, U/D Limits = 50000/50000
03:04:43		Shutdown load counter = 1
03:04:43		Login with UserName '***********@gmail.com'
03:04:52	... Login success
03:04:53		Server is being created
03:04:53	... Server name 'COMBAT BOX by Red Flight'
03:04:53		Loading mission 'Multiplayer/Dogfight\Alonzo\Operation_Frantic\Operation-Frantic-June-1944.msnbin' (Multiplayer/Dogfight\Alonzo\Operation_Frantic\Operation-Frantic-June-1944)...
03:04:53		Server listener IP = '192.168.1.29'
03:04:58	... Mission loaded successfully
03:04:58	Server succesfully registered on master server
03:06:19		RCON: New incoming connection [0]: 127.0.0.1: 63260
04:33:54	
=====	Rotation is in progress (2 seconds to wait before loading)	=====
04:33:54	Shutdown count reached. Server quits automaticly

04:33:54	=====	Server uninit	=====

 

But in fact the server left a dserver.exe process running, and didn't quit, and so my control script just sat there waiting. Now I have a new check that looks for a log file like this and understands if the server thinks it quit, but didn't.

Edited July 7, 2019 by Alonzo

[Habu]

Reading the log seems that the deserver quits and don't crash. Careful there is your mail in the log you post, delete it.

 

Here is one of mine :

 

Quote

14:20:54    =====    DeathMatch mode    =====
14:20:54    =====    Dedicated server    =====
14:20:54    Brief info:
14:20:54        Max clients = 85
14:20:54        TCP: 28002, UDP: 28002, Downloader: 28102, U/D Limits = 90000/90000
14:20:54        Login with UserName 'XXXXXXXXXXXXXX'
14:20:59    ... Login success
14:21:00        Server is being created
14:21:00    ... Server name 'Vercingetorix Beta Dedicated Server'
14:21:00        Loading mission 'Multiplayer/Dogfight\PX_Training_Kuban_Sum_v2.2_N.msnbin' (Multiplayer/Dogfight\PX_Training_Kuban_Sum_v2.2_N)...
14:21:00        Server listener IP = 'XXX.XXX.XXX.XXX
14:21:04    ... Mission loaded successfully
14:21:04    Server succesfully registered on master server
14:31:27    =====    Server uninit    =====

 

 

Alonzo, if you want i can put my server with your mision online and open for one day, to see, because we can test only between 1 to 10 players. So i can't have similar condition, it would be better to have the same condition.

 

If you are ok, tell me when, and put your SDS (without your login/password, i'll use mine).

Edited July 7, 2019 by Habu

[Alonzo]

6 hours ago, Habu said:

Reading the log seems that the deserver quits and don't crash. Careful there is your mail in the log you post, delete it.

 

Thank you for the heads up, I have removed the email.

 

The problem is that dserver thinks it has quit, but actually a dserver.exe process is still running in Windows. I can see it in task manager as a background task, but there is no window any more. I updated my control script to detect this state -- if the log file says "Server uninit" but there is still a dserver.exe, then the server did not shut down cleanly. But what I really want to do is run several maps in a rotation, not just one at a time. My theory is that this problem with the server stopping cleanly is the same as the problem where, if I set multiple missions in one SDS file, the server appears to roll to the next map but actually gets stuck -- it thinks it has started the next map but cannot actually accept players.

 

For your test server, do you need me to provide some players to help test, or do you have testers? Sorry if this sounds like a silly question, but I do not know the situation. I can find some people to help test but I would need to coordinate a time for them.

[Habu]

I can have between 5 or 10 tester, so if you can have more, it will be better.

[JimTM]

4 hours ago, Alonzo said:

...

The problem is that dserver thinks it has quit, but actually a dserver.exe process is still running in Windows. I can see it in task manager as a background task, but there is no window any more. I updated my control script to detect this state -- if the log file says "Server uninit" but there is still a dserver.exe, then the server did not shut down cleanly. But what I really want to do is run several maps in a rotation, not just one at a time. My theory is that this problem with the server stopping cleanly is the same as the problem where, if I set multiple missions in one SDS file, the server appears to roll to the next map but actually gets stuck -- it thinks it has started the next map but cannot actually accept players.

...

 

Just a thought from a newb when it comes to using scripts to control DServer: I notice that the dserver.exe process starts when you open the DServer interface and stops when you close it. I did not see any process that starts/stops when you start/stop a mission. Does the server stop when the mission ends or does it stop when you shut down the DServer interface?

Edited July 7, 2019 by JimTM

[LLv34_Temuri]

On 7/7/2019 at 3:42 PM, Alonzo said:

The problem is that dserver thinks it has quit, but actually a dserver.exe process is still running in Windows.

We had this with our earlier system version. The generated missions would be so heavy, that the dserver would be left hanging in the background. That's why we had the system kill all dserver processes when a hang occurred.