NetServer FSM update (type=25 state=3) error when closing the game in the loading screen

[elexis]

As reported by fatherbushido, with r19647 one can receive this error when closing the game with Alt+F4 in the loading screen sometimes:

Net server: Error running FSM update (type=25 state=3)</p>

state 3 is SERVER_STATE_INGAME type 23 is NMT_LOADED_GAME

Notice in my logfile there is this CEndCommandBatchMessage just before:

<p>Net message: ({type:"gamesetup", data:{settings:{PlayerData:[{Name:"elexis2", Civ:"pers", Color:{r:46, g:46, b:200}, AI:"", AIDiff:3, Team:0, Teams:-1}, {Name:"Player 2", Civ:"ptol", Color:{r:150, g:20, b:20}, AI:"", AIDiff:3, Team:0, Teams:-1}, {Name:"Player 3", Civ:"pers", Color:{r:50, g:165, b:5}, AI:"", AIDiff:3, Team:0, Teams:-1}, {Name:"Player 4", Civ:"pers", Color:{r:230, g:230, b:75}, AI:"", AIDiff:3, Team:1, Teams:-1}, {Name:"Player 5", Civ:"cart", Color:{r:50, g:170, b:170}, AI:"", AIDiff:3, Team:1, Teams:-1}, {Name:"Player 6", Civ:"mace", Color:{r:160, g:80, b:200}, AI:"", AIDiff:3, Team:1, Teams:-1}], CheatsEnabled:false, CircularMap:true, Size:128, GameType:"conquest", VictoryScripts:["scripts/TriggerHelper.js", "scripts/ConquestCommon.js", "scripts/Conquest.js"], WonderDuration:20, PopulationCap:200, Ceasefire:0, StartingResources:300, RatingEnabled:false, LockTeams:true, LastManStanding:false, Name:"Pyrenean Sierra", Script:"pyrenean_sierra.js", Description:"High mountains separating the enemies.\n\nThe Pyrenees is a great mountain range located between modern France and Spain.", BaseTerrain:["alpine_dirt_grass_50"], BaseHeight:-100, Preview:"pyrenean_sierra.png", Keywords:["new"], DisabledTemplates:["structures/ptol_lighthouse"], RelicCount:5, VictoryDuration:20, RegicideGarrison:false, RevealMap:false, ExploreMap:false, DisableTreasures:false, DisableSpies:false, TriggerScripts:["scripts/TriggerHelper.js", "scripts/ConquestCommon.js", "scripts/Conquest.js"], mapType:"random", Seed:2341313673, AISeed:2180731333}, mapType:"random", mapPath:"maps/random/", mapFilter:"default", gameSpeed:1, map:"maps/random/pyrenean_sierra", script:"pyrenean_sierra.js", matchID:"7CA5ABAAF741FE58", timestamp:1495631343, engine_version:"0.0.22", mods:["mod", "public"]}})</p>
<p>Net message: ({type:"players", newAssignments:{'1F79CD5B94A0DEF3':{name:"elexis2", player:1, status:2}}})</p>
<p>Net message: ({type:"start"})</p>
<p>'art/terrains/terrains.xml' does not exist. Using previous properties.</p>
<p>Loading RMS 'maps/random/pyrenean_sierra.js'</p>
<p>Loading map generator script 'maps/random/rmgen/area.js'</p>
<p>Loading map generator script 'maps/random/rmgen/constraint.js'</p>
<p>Loading map generator script 'maps/random/rmgen/entity.js'</p>
<p>Loading map generator script 'maps/random/rmgen/environment.js'</p>
<p>Loading map generator script 'maps/random/rmgen/library.js'</p>
<p>Loading map generator script 'maps/random/rmgen/map.js'</p>
<p>Loading map generator script 'maps/random/rmgen/mapgen.js'</p>
<p>Loading map generator script 'maps/random/rmgen/misc.js'</p>
<p>Loading map generator script 'maps/random/rmgen/noise.js'</p>
<p>Loading map generator script 'maps/random/rmgen/painter.js'</p>
<p>Loading map generator script 'maps/random/rmgen/pathplacer.js'</p>
<p>Loading map generator script 'maps/random/rmgen/placer.js'</p>
<p>Loading map generator script 'maps/random/rmgen/point.js'</p>
<p>Loading map generator script 'maps/random/rmgen/random.js'</p>
<p>Loading map generator script 'maps/random/rmgen/randombiome.js'</p>
<p>Loading map generator script 'maps/random/rmgen/terrain.js'</p>
<p>Loading map generator script 'maps/random/rmgen/tileclass.js'</p>
<p>Loading map generator script 'maps/random/rmgen/utilityfunctions.js'</p>
<p>Loading map generator script 'maps/random/rmgen/wall_builder.js'</p>
<p>Initializing map...</p>
<p>Creating new map...</p>
<p>Net: Sending message CEndCommandBatchMessage { m_Turn: 2, m_TurnLength: 0 } of size 9 to server</p>
<p>Net server: Received message CEndCommandBatchMessage { m_Turn: 2, m_TurnLength: 0 } of size 9 from [1F79CD5B...]</p>
<p class="error">ERROR: Net server: Error running FSM update (type=25 state=3)</p>
<p>Creating base for player 3...</p>
<p>Creating base for player 4...</p>
<p>Creating base for player 2...</p>
<p>Creating base for player 6...</p>
<p>Creating base for player 1...</p>
<p>Creating base for player 5...</p>
<p>Creating the pyreneans...</p>
<p>creating Oceans</p>
<p>Shutting down profiler2 GPU mode</p>

[Imarok]

Replying to elexis:

As reported by fatherbushido, with r19647 one can receive this error when closing the game with Alt+F4 in the loading screen sometimes:

Net server: Error running FSM update (type=25 state=3)</p>

state 3 is SERVER_STATE_INGAME type 23 is NMT_LOADED_GAME

In the error message it says type 25 that is NMT_END_COMMAND_BATCH

That looks related to ​https://trac.wildfiregames.com/ticket/3199#comment:9

[Imarok]

Also got this when testing ​Phab:D1513

[Imarok]

Looks like something with the turnmanager, so adding echotangoecho as CC. I uploaded an excerpt of the mainlog to ​Phab:D123

[elexis]

I can confirm that this error still occurs and can reproduce it occasionally when pressing Alt+F4.

Creating patrol points for ships... 0.079s.
Creating ungarrison points for ships...^CERROR: Net server: Error running FSM update (type=25 state=4)
WARNING: Quit requested!

Generating Danubius of size 128 and 2 players.
Creating playerbases... 0.053s.
Creating river...WARNING: Quit requested!
ERROR: Net server: Error running FSM update (type=25 state=4)
WARNING: JavaScript warning: globalscripts/vector.js line 11
Script terminated by timeout at:
Vector2D@globalscripts/vector.js:11:1
Vector2D.prototype.perpendicular@globalscripts/vector.js:118:9
paintRiver@maps/random/rmgen-common/gaia_terrain.js:376:39
@maps/random/danubius.js:369:1

ERROR: CMapGeneratorWorker::Run: Failed to load RMS 'maps/random/danubius.js'

mainlog.html:

<p>Generating Danubius of size 256 and 2 players.
</p>
<p>Creating gallic villages...</p>
<p>Net: Sending message CEndCommandBatchMessage { m_Turn: 2, m_TurnLength: 0 } of size 9 to server</p>
<p>Net server: Received message CEndCommandBatchMessage { m_Turn: 2, m_TurnLength: 0 } of size 9 from [72025502...]</p>
<p class="error">ERROR: Net server: Error running FSM update (type=25 state=4)</p>
<p class="warning">WARNING: Quit requested!</p>

[elexis]

Called from CNetClientTurnManager::NotifyFinishedOwnCommands according to debug_printf.

This looks a lot like it comes from CNetClientTurnManager::OnDestroyConnection(). debug_printf confirms. (This is called from CNetClient::DestroyConnection() which is called from ~CNetClient().)

One may wonder if the command is wrong there, but it appears to make sense. The idea must be that the last turn of the replay file still contains all commands.

So all of this is probably a race condition, the mapgen in running a thread separate to the NetClient.

The fix is most likely to not send this ingame message if not ingame.

EDIT: NotifyFinishedOwnCommands is always called, the CEndCommandBatchMessage is always sent, it's just not always received until the shutdown! Not sure if the send can fail too, jeopardizing the idea of the feature. But at least the FSM state warning should be fixed.

EDIT 2: Same bug in a different state exists too:

ERROR: Net server: Error running FSM update (type=25 state=5) NMT_END_COMMAND_BATCH while NSS_JOIN_SYNCING

[elexis]

The idea must be that the last turn of the replay file still contains all commands.

Probably rather that the client is marked as "done with this turn" immediately, so as to remove any waiting times for the next turn.

[elexis]

Nope.

The truth is ​Phab:rP14732 introduced it and the idea was to prevent exit-button rating evasion as mentioned by sanderd17 in #2373.

The means are to send the resign simulation command, flush the simulation commands and instantly destroy the netclient and game, which up to this day never worked and cannot work because the NetClient destructor doesn't wait for the server to reflect packets (which could consume an arbitrary amount of time).

The commits have other bugs too.

[elexis]

In 21837:

Fix network FSM errors when a client closes the game during the loading screen or rejoin synchronization stage, fixes #4594, refs 3199.

Fix comments claiming to ensure reliability when in reality there is only a small likelihood of the message being received.

Broken by rP14732 / refs #2420 which was a preparation for rP14772 / refs #2373, which hence didn't actually work and was circumvented by rP15106 without clarification.
Might have caused #3643.
Differential Revision: ​https://code.wildfiregames.com/D1557
Reviewed By: Imarok