Openspades: Map change triggered error.
Sat Sep 14 05:55:48 2013 [..\..\Sources\Client\NetClient.cpp:1727] Map decoding succeeded. Sat Sep 14 05:55:48 2013 [..\..\Sources\Client\GameMapWrapper.cpp:106] 71.056 msecs to rebuild Sat Sep 14 05:55:48 2013 [..\..\Sources\Client\NetClient.cpp:1732] World initialized. Sat Sep 14 05:55:48 2013 [..\..\Sources\Client\Client.cpp:229] World set Sat Sep 14 05:55:48 2013 [..\..\Sources\Draw\GLRenderer.cpp:251] New map loaded; freeing old renderers... Sat Sep 14 05:55:48 2013 [..\..\Sources\Draw\GLRenderer.cpp:266] Creating new renderers... Sat Sep 14 05:55:48 2013 [..\..\Sources\Draw\GLRenderer.cpp:268] Creating Terrain Shadow Map Renderer Sat Sep 14 05:55:48 2013 [..\..\Sources\Draw\GLRenderer.cpp:270] Creating TerrainRenderer Sat Sep 14 05:55:48 2013 [..\..\Sources\Draw\GLRenderer.cpp:272] Creating Minimap Renderer Sat Sep 14 05:55:48 2013 [..\..\Sources\Draw\GLRenderer.cpp:274] Creating Water Renderer Sat Sep 14 05:55:48 2013 [..\..\Sources\Draw\GLRenderer.cpp:278] Creating Ray-traced Ambient Occlusion Renderer Sat Sep 14 05:55:48 2013 [..\..\Sources\Draw\GLAmbientShadowRenderer.cpp:97] Chunk buffer allocated (67289088 bytes) Sat Sep 14 05:55:48 2013 [..\..\Sources\Draw\GLAmbientShadowRenderer.cpp:124] Chunk texture allocated Sat Sep 14 05:55:48 2013 [..\..\Sources\Draw\GLAmbientShadowRenderer.cpp:139] Chunk texture initialized Sat Sep 14 05:55:48 2013 [..\..\Sources\Draw\GLRenderer.cpp:280] Creating Relective Shadow Maps Renderer Sat Sep 14 05:55:48 2013 [..\..\Sources\Draw\GLRadiosityRenderer.cpp:123] Chunk buffer allocated (268615680 bytes) Sat Sep 14 05:55:48 2013 [..\..\Sources\Draw\GLRadiosityRenderer.cpp:160] Chunk texture allocated Sat Sep 14 05:55:49 2013 [..\..\Sources\Draw\GLRadiosityRenderer.cpp:181] Chunk texture initialized Sat Sep 14 05:55:49 2013 [..\..\Sources\Draw\GLRenderer.cpp:289] Created Sat Sep 14 05:55:49 2013 [..\..\Sources\Client\NetClient.cpp:1741] World loaded. Processing saved packets (71)... Sat Sep 14 05:55:49 2013 [..\..\Sources\Client\NetClient.cpp:406] Waiting for graceful disconnection Sat Sep 14 05:55:49 2013 [..\..\Sources\Client\Client.cpp:439] Disconnected because of error: [..\..\Sources\Client\NetClient.cpp:622] Invalid Player ID 12: Doesn't exist Collected backtrace: ?GetPlayer@NetClient@client@spades@@AAEPAVPlayer@23@H@Z at ..\..\Sources\Client\NetClient.cpp:616 ?Handle@NetClient@client@spades@@AAEXAAVNetPacketReader@23@@Z at ..\..\Sources\Client\NetClient.cpp:679 ?MapLoaded@NetClient@client@spades@@AAEXXZ at ..\..\Sources\Client\NetClient.cpp:1720 ?DoEvents@NetClient@client@spades@@QAEXH@Z at ..\..\Sources\Client\NetClient.cpp:431 ?RunFrame@Client@client@spades@@QAEXM@Z at ..\..\Sources\Client\Client.cpp:414 ?Run@SDLRunner@gui@spades@@UAEXXZ at ..\..\Sources\Gui\SDLRunner.cpp:220 ?StartGame@MainWindow@@AAEXABV?$basic_string@DU?$char_traits@D@std@@V?$allocator@D@2@@std@@@Z at ..\..\Sources\Gui\MainWindowHandler.cpp:86 ?QuickConnectPressed@MainWindow@@AAEXXZ at ..\..\Sources\Gui\MainWindowHandler.cpp:135 main at ..\..\Sources\Gui\Main.cpp:68
learn-more
All 14 comments
This is still relevant, I've had this happen a few times. Seems to be completely random, maybe caused by late Packets arriving from server after round has finished and Player objects have been deleted.
NotAFile
on 14 Sep 2015
Yeah, that's about the gist of the problem.
learn-more
on 14 Sep 2015
Do you know enough about this error to fix it? I don't know enough C++ to do anything about this unfortunately.
NotAFile
on 16 Sep 2015
I have not looked into it, nor anything AoS related in months...
learn-more
on 16 Sep 2015
I've been doing so very intensely for the last few days and Its becoming increasingly depressing
NotAFile
on 17 Sep 2015
AFAIK this error was introduced during one of the codebase optimisations/rewritings. You can try and track it down with git bisect or something. Or maybe I am just speculating because of wrong impression of the ancient changes.
noway
on 20 Sep 2015
Still present in the master branch. I get it almost every time the map changes. Perhaps could we just make it ignore an invalid player ID like the original client didn't do any error checks?
yvt
on 22 Nov 2016
@yvt can this be added to 0.1.2 milestone? It's a very old and recurrent bug that should've been solved quite some time ago.
feikname
on 28 Feb 2017
Is this solved? I've been using master for a while and it's not been an issue again.
NotAFile
on 2 Dec 2017
I couldn't find any commits made specifically to fix this, perhaps it got accidentally fixed in master? Or maybe you just were lucky, dunno.
If we had a deterministic way to trigger the bug, it would be easy to prove.
feikname
on 3 Dec 2017
The issue is still present:
2017/12/16 02:10:26 [NetClient.cpp:264] Packet 0x03 [len=3] 03 1a 20
2017/12/16 02:10:26 [NetClient.cpp:264] Packet 0x03 [len=3] 03 00 25
2017/12/16 02:10:26 [NetClient.cpp:264] Packet 0x02 [len=769] 02 32 cd 98 43 db 0d bc 43 61 98 52 42 96 39 7a bf e9 96 57 3e 59 5d 89 3c 0a 34 4a 43 98 0c c4 43 ae fc 62 42 3d 1b 51 bd d7 9f 7f bf 0a f3 93 3c 5b 85 4e 43 85 09 c5 43 db e4 62 42 00 f1 1c
2017/12/16 02:10:26 [NetClient.cpp:264] Packet 0x04 [len=3] 04 1e 02
2017/12/16 02:10:26 [NetClient.cpp:1772] Map decoding succeeded.
2017/12/16 02:10:26 [GameMapWrapper.cpp:101] 4.795 msecs to rebuild
2017/12/16 02:10:26 [NetClient.cpp:1778] World initialized.
2017/12/16 02:10:26 [Client.cpp:170] World set
2017/12/16 02:10:26 [GLRenderer.cpp:324] New map loaded; freeing old renderers...
2017/12/16 02:10:26 [GLRenderer.cpp:338] Creating new renderers...
2017/12/16 02:10:26 [GLRenderer.cpp:340] Creating Terrain Shadow Map Renderer
2017/12/16 02:10:26 [GLRenderer.cpp:342] Creating TerrainRenderer
2017/12/16 02:10:26 [GLRenderer.cpp:344] Creating Minimap Renderer
2017/12/16 02:10:26 [GLRenderer.cpp:346] Creating Water Renderer
2017/12/16 02:10:26 [GLRenderer.cpp:350] Creating Ray-traced Ambient Occlusion Renderer
2017/12/16 02:10:26 [GLAmbientShadowRenderer.cpp:83] Chunk buffer allocated (67289088 bytes)
2017/12/16 02:10:26 [GLAmbientShadowRenderer.cpp:99] Chunk texture allocated
2017/12/16 02:10:26 [GLAmbientShadowRenderer.cpp:109] Chunk texture initialized
2017/12/16 02:10:26 [GLRenderer.cpp:352] Creating Relective Shadow Maps Renderer
2017/12/16 02:10:26 [GLRadiosityRenderer.cpp:104] Chunk buffer allocated (268615680 bytes)
2017/12/16 02:10:26 [GLRadiosityRenderer.cpp:133] Chunk texture allocated
2017/12/16 02:10:26 [GLRadiosityRenderer.cpp:150] Chunk texture initialized
2017/12/16 02:10:26 [GLRenderer.cpp:360] Created
2017/12/16 02:10:26 [NetClient.cpp:1786] World loaded. Processing saved packets (191)...
2017/12/16 02:10:26 [NetClient.cpp:442] Waiting for graceful disconnection
2017/12/16 02:10:27 [Client.cpp:408] Disconnected because of error:
Invalid Player ID 24: Doesn't exist
at /Users/tcpp/Programs/Games/openspades/Sources/Client/NetClient.cpp:664
spades::client::Player *spades::client::NetClient::GetPlayer(int) at NetClient.cpp:658
void spades::client::NetClient::Handle(spades::client::NetPacketReader &) at NetClient.cpp:719
void spades::client::NetClient::MapLoaded() at NetClient.cpp:1766
void spades::client::NetClient::DoEvents(int) at NetClient.cpp:476
virtual void spades::client::Client::RunFrame(float) at Client.cpp:380
virtual void spades::gui::MainScreen::RunFrame(float) at MainScreen.cpp:232
void spades::gui::SDLRunner::Run(int, int) at SDLRunner.cpp:483
void spades::gui::Runner::Run() at Runner.cpp:72
void spades::gui::Runner::RunProtected() at Runner.cpp:44
int main(int, char **) at Main.cpp:312
I started to develop a habit of disconnecting right before the map change and then reconnecting after that.
yvt
on 15 Dec 2017
Huh. It's probably related to you living far away from the servers... If the theory of this being caused by delayed world update packets is correct. Either way, I guess it would be relatively simple to write a quick script to send a mapstart packet and then a worldupdate packet
NotAFile
on 16 Dec 2017
It probably has something to do with the world update packet handling during map loading sequence where OS defers the processing of received packets until entire the map is loaded (in case of the server failing to do that). The longer map loading time, the more deferred packets, which produce more chance of triggering this bug.
yvt
on 16 Dec 2017
I think I found the cause. See this log:
https://gist.github.com/yvt/f61333951858988d9c8f1fa40e436f40
It says Invalid Player ID 24: Doesn't exist but there exists no CreatePlayer (0x0c) packet for the player ID 24 sent by the server. Instead, there is a WeaponReload (0x1c) packet for that player which is sent even before StateData (0x0f):
2017/12/16 02:10:03 [NetClient.cpp:264] Packet 0x1c [len=4] 1c 18 0a 28
Here’s a speculation of what is happening here:
- World update packets from the last round
MapStart(indicates the start of a new round)MapChunks- Leftover world update packets from the last round
StateData- World update packets from the current round
- The last
MapChunks — OS processes all saved packets, but crashes when processing 4 because the state of the last round is already destroyed at the point of 2
yvt
on 16 Dec 2017
Related issues
parkerlreed
·
4Comments
Danogot516
·
3Comments
NotAFile
·
5Comments
damienflament
·
7Comments
Mailaender
·
7Comments
Most helpful comment
I think I found the cause. See this log:
https://gist.github.com/yvt/f61333951858988d9c8f1fa40e436f40
It says
Invalid Player ID 24: Doesn't existbut there exists noCreatePlayer(0x0c) packet for the player ID 24 sent by the server. Instead, there is aWeaponReload(0x1c) packet for that player which is sent even beforeStateData(0x0f):Here’s a speculation of what is happening here:
MapStart(indicates the start of a new round)MapChunksStateDataMapChunks — OS processes all saved packets, but crashes when processing 4 because the state of the last round is already destroyed at the point of 2