Opened 7 years ago
Closed 6 years ago
#4594 closed defect (fixed)
NetServer FSM update (type=25 state=3) error when closing the game in the loading screen
Reported by: | elexis | Owned by: | elexis |
---|---|---|---|
Priority: | Should Have | Milestone: | Alpha 23 |
Component: | Network | Keywords: | |
Cc: | Patch: | Phab:D1557 |
Description
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>
Attachments (1)
Change History (10)
by , 7 years ago
Attachment: | mainlog.html added |
---|
comment:1 by , 6 years ago
comment:3 by , 6 years ago
Cc: | added |
---|
Looks like something with the turnmanager, so adding echotangoecho as CC. I uploaded an excerpt of the mainlog to Phab:D123
comment:4 by , 6 years ago
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>
comment:5 by , 6 years ago
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
comment:6 by , 6 years ago
Cc: | removed |
---|---|
Milestone: | Backlog → Work In Progress |
Patch: | → Phab:D1557 |
comment:7 by , 6 years ago
Milestone: | Work In Progress → Alpha 23 |
---|---|
Priority: | Nice to Have → Should Have |
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.
comment:8 by , 6 years ago
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.
Replying to elexis:
In the error message it says
type 25
that isNMT_END_COMMAND_BATCH
That looks related to https://trac.wildfiregames.com/ticket/3199#comment:9