Map change triggered error. #66

learn-more · 2013-09-14T03:59:56Z

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

NotAFile · 2015-09-13T22:33:16Z

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.

learn-more · 2015-09-14T21:22:50Z

Yeah, that's about the gist of the problem.

NotAFile · 2015-09-16T07:13:46Z

Do you know enough about this error to fix it? I don't know enough C++ to do anything about this unfortunately.

learn-more · 2015-09-16T17:27:57Z

I have not looked into it, nor anything AoS related in months...

NotAFile · 2015-09-16T23:41:28Z

I've been doing so very intensely for the last few days and Its becoming increasingly depressing

noway · 2015-09-20T11:27:40Z

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.

yvt · 2016-11-22T17:04:43Z

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?

feikname · 2017-02-28T02:54:52Z

@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.

NotAFile · 2017-12-02T14:01:42Z

Is this solved? I've been using master for a while and it's not been an issue again.

feikname · 2017-12-03T05:12:08Z

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.

yvt · 2017-12-15T17:42:43Z

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.

NotAFile · 2017-12-15T23:44:55Z

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

yvt · 2017-12-16T04:30:22Z

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 · 2017-12-16T05:00:23Z

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

Fixes #66. Wow, it's been 4 years since the issue was reported for the first time. *Inhale* yay!

yvt mentioned this issue Nov 22, 2016

Sometimes client crashes with 'Invalid Player ID' error after map switch. #277

Closed

yvt mentioned this issue Nov 22, 2016

Invalid player ID error on map change. #458

Closed

feikname mentioned this issue Jan 8, 2017

Strange network protocol issue or something else #536

Closed

NotAFile mentioned this issue Feb 27, 2017

Netclient.cpp #588

Closed

yvt added the AoSβ compatibility label Feb 28, 2017

yvt added this to the 0.1.2 milestone Feb 28, 2017

VelocityRa mentioned this issue Mar 17, 2017

"Invalid Player" error during map change #600

Closed

yvt closed this as completed in 01f21eb Dec 16, 2017

yvt added a commit that referenced this issue Dec 16, 2017

Fix "invalid player ID" error after map change

d7768ae

Fixes #66. Wow, it's been 4 years since the issue was reported for the first time. *Inhale* yay!

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Map change triggered error. #66

Map change triggered error. #66

learn-more commented Sep 14, 2013

NotAFile commented Sep 13, 2015

learn-more commented Sep 14, 2015

NotAFile commented Sep 16, 2015

learn-more commented Sep 16, 2015

NotAFile commented Sep 16, 2015

noway commented Sep 20, 2015

yvt commented Nov 22, 2016 •

edited

Loading

feikname commented Feb 28, 2017

NotAFile commented Dec 2, 2017

feikname commented Dec 3, 2017 •

edited

Loading

yvt commented Dec 15, 2017

NotAFile commented Dec 15, 2017

yvt commented Dec 16, 2017

yvt commented Dec 16, 2017

Map change triggered error. #66

Map change triggered error. #66

Comments

learn-more commented Sep 14, 2013

NotAFile commented Sep 13, 2015

learn-more commented Sep 14, 2015

NotAFile commented Sep 16, 2015

learn-more commented Sep 16, 2015

NotAFile commented Sep 16, 2015

noway commented Sep 20, 2015

yvt commented Nov 22, 2016 • edited Loading

feikname commented Feb 28, 2017

NotAFile commented Dec 2, 2017

feikname commented Dec 3, 2017 • edited Loading

yvt commented Dec 15, 2017

NotAFile commented Dec 15, 2017

yvt commented Dec 16, 2017

yvt commented Dec 16, 2017

yvt commented Nov 22, 2016 •

edited

Loading

feikname commented Dec 3, 2017 •

edited

Loading