0001142: Game crashes after starting battle if folder /usr/share/vcmi/Mods is not owned by root

Notes
(0003176) Ivan (developer) 2012-10-11 17:33 edited on: 2012-10-11 17:59	Strange. I have whole /usr/share/vcmi directory owned by me - everything OK. Looks like crash on server. Can you upload logs? EDIT: copied vcmi directory without symlinks, changed owner to root/root. Got some "permission denied" crashes. (log is different from yours) Fixed by "chmod -R a+rx /usr/share/vcmi" Changing owner does not changes anything in game.

(0003177) beegee (developer) 2012-10-11 17:58 edited on: 2012-10-11 17:59	This is the server log located in .vcmi/server_log.txt. Those cryptic codes come from the console coloring(should be removed...) [1;32m Initialization: [0m[1;32m0[0m [1;32m[0m[1;32m[0m[1;32m Data loading: [0m[1;32m60[0m [1;32m Found mod filesystem: [0m[1;32mALL/MODS/VCMI/FILESYSTEM[0m[1;32m [0m[1;32m[0m[1;32m[0m[1;32m Found mod filesystem: [0m[1;32mALL/MODS/WOG/FILESYSTEM[0m[1;32m [0m[1;32m[0m[1;32m[0m[1;32m Mod filesystems: [0m[1;32m0[0m [1;32mFile system handler: [0m[1;32m60[0m [1;32mPort [0m[1;32m3030[0m[1;32m will be used.[0m [1;32m[0m[1;32m[0m[1;32m Mod handler: [0m[1;32m0[0m [1;32m General text handler: [0m[1;32m0[0m [1;32m[0m[1;32m[0m[1;32m[0m[1;32m[0m[1;32m[0m[1;32m[0m[1;32m Hero handler: [0m[1;32m20[0m [1;32m[0m[1;32m[0m[1;32m Artifact handler: [0m[1;32m0[0m [1;32m[0m[1;32m[0m[1;32m[0m[1;32m[0m[1;32m[0m[1;32m[0m[1;32m[0m[1;32m[0m[1;32m Creature handler: [0m[1;32m30[0m [1;32m[0m[1;32m[0m[1;32m Town handler: [0m[1;32m20[0m [1;32m[0m[1;32m[0m[1;32m[0m[1;32m[0m[1;32m[0m[1;32m[0m[1;32m Object handler: [0m[1;32m0[0m [1;32m Def information handler: [0m[1;32m30[0m [1;32m[0m[1;32m[0m[1;32m Spell handler: [0m[1;32m10[0m [1;39mCVCMIServer created![0m [1;32mListening for connections at port [0m[1;32m3030[0m [1;32mWe've accepted someone... [0m [1;32mEstablished connection with [0m[1;32mVCMI 0.9 (client)[0m [1;32mGot connection![0m [1;32mGamestate created![0m [1;32m Using random seed: [0m[1;32m1349973848[0m [1;32mOpening map file: [0m[1;32mMAPS/FOR SALE[0m[1;32m [0m[1;32mdone.[0m [1;32m Our map checksum: [0m[1;32m446597263[0m [1;32m Reading header: [0m[1;32m0[0m [1;32m Reading rumors: [0m[1;32m0[0m [1;32m Reading predefined heroes: [0m[1;32m0[0m [1;32m Reading terrain: [0m[1;32m0[0m [1;32m Reading defs info: [0m[1;32m10[0m [1;32m[0m[1;32m[0m[1;32m[0m[1;32m[0m[1;32m[0m[1;32m[0m[1;32m[0m[1;32m[0m[1;32m[0m[1;32m[0m[1;32m[0m[1;32m[0m[1;32m Reading objects: [0m[1;32m10[0m [1;32m Reading events: [0m[1;32m0[0m [1;32m Calculating blocked/visitable tiles: [0m[1;32m0[0m [1;32m Map initialization done![0m [1;32mMap loaded![0m [1;32m Our checksum for the map: [0m[1;32m446597263[0m [1;32m[0m[1;32m[0m[1;39mInitialization:[0m[1;39m Picking grail position[0m[1;39m Picking random factions for players[0m[1;39m Randomizing objects[0m[1;39m Creating player entries in gs[0m[1;39m Giving starting hero[0m[1;39m Replacing hero placeholders[0m[1;39m Setting up resources[0m[1;32m[0m[1;32m[0m[1;39m Setting up heroes[0m[1;39m Fog of war[0m[1;39m Starting bonuses[0m[1;39m Towns[0m[1;39m Object initialization[0m[1;39m Checking objectives[0m[1;32mSeed after init is [0m[1;32m1715710325[0m[1;32m (before was [0m[1;32m1349973848[0m[1;32m)[0m [1;32mGamestate initialized![0m [1;32mConnection [0m[1;32m1[0m[1;32m will handle [0m[1;32m4[0m[1;32m player: [0m[1;32m0[0m[1;32m [0m[1;32m1[0m[1;32m [0m[1;32m2[0m[1;32m [0m[1;32m255[0m[1;32m [0m [1;32mconst PlayerState* CGameInfoCallback::getPlayer(int, bool) const[0m[1;32m: [0m[1;32mCannot find player [0m[1;32m3[0m[1;32minfo![0m [1;32mconst PlayerState* CGameInfoCallback::getPlayer(int, bool) const[0m[1;32m: [0m[1;32mCannot find player [0m[1;32m4[0m[1;32minfo![0m [1;32mconst PlayerState* CGameInfoCallback::getPlayer(int, bool) const[0m[1;32m: [0m[1;32mCannot find player [0m[1;32m5[0m[1;32minfo![0m [1;32mconst PlayerState* CGameInfoCallback::getPlayer(int, bool) const[0m[1;32m: [0m[1;32mCannot find player [0m[1;32m6[0m[1;32minfo![0m [1;32mconst PlayerState* CGameInfoCallback::getPlayer(int, bool) const[0m[1;32m: [0m[1;32mCannot find player [0m[1;32m7[0m[1;32minfo![0m [1;32mconst PlayerState* CGameInfoCallback::getPlayer(int, bool) const[0m[1;32m: [0m[1;32mCannot find player [0m[1;32m3[0m[1;32minfo![0m [1;32mconst PlayerState* CGameInfoCallback::getPlayer(int, bool) const[0m[1;32m: [0m[1;32mCannot find player [0m[1;32m4[0m[1;32minfo![0m [1;32mconst PlayerState* CGameInfoCallback::getPlayer(int, bool) const[0m[1;32m: [0m[1;32mCannot find player [0m[1;32m5[0m[1;32minfo![0m [1;32mconst PlayerState* CGameInfoCallback::getPlayer(int, bool) const[0m[1;32m: [0m[1;32mCannot find player [0m[1;32m6[0m[1;32minfo![0m [1;32mconst PlayerState* CGameInfoCallback::getPlayer(int, bool) const[0m[1;32m: [0m[1;32mCannot find player [0m[1;32m7[0m[1;32minfo![0m [1;32mSaving to [0m[1;32mSaves/Newgame_Autosave_1[0m[1;32m [0m[1;32mOrdering clients to serialize... [0m[1;32mSerializing game info... [0m[1;32mSerializing server info... [0m[1;32mGame has been successfully saved! [0m[1;32mconst PlayerState* CGameInfoCallback::getPlayer(int, bool) const[0m[1;32m: [0m[1;32mCannot find player [0m[1;32m3[0m[1;32minfo![0m [1;32mconst PlayerState* CGameInfoCallback::getPlayer(int, bool) const[0m[1;32m: [0m[1;32mCannot find player [0m[1;32m4[0m[1;32minfo![0m [1;32mconst PlayerState* CGameInfoCallback::getPlayer(int, bool) const[0m[1;32m: [0m[1;32mCannot find player [0m[1;32m5[0m[1;32minfo![0m [1;32mconst PlayerState* CGameInfoCallback::getPlayer(int, bool) const[0m[1;32m: [0m[1;32mCannot find player [0m[1;32m6[0m[1;32minfo![0m [1;32mconst PlayerState* CGameInfoCallback::getPlayer(int, bool) const[0m[1;32m: [0m[1;32mCannot find player [0m[1;32m7[0m[1;32minfo![0m [1;39mCreating a query for player [0m[1;39m0[0m[1;39m with ID=[0m[1;39m1[0m [1;39mCreating a query for player [0m[1;39m0[0m[1;39m with ID=[0m[1;39m2[0m [1;32m[0m[1;32m[0m VCMI_Server_Log.txt(just the last part): const PlayerState* CGameInfoCallback::getPlayer(int, bool) const: Cannot find player 3info! const PlayerState* CGameInfoCallback::getPlayer(int, bool) const: Cannot find player 4info! const PlayerState* CGameInfoCallback::getPlayer(int, bool) const: Cannot find player 5info! const PlayerState* CGameInfoCallback::getPlayer(int, bool) const: Cannot find player 6info! const PlayerState* CGameInfoCallback::getPlayer(int, bool) const: Cannot find player 7info! Sending to all clients a package of type 9HeroVisit Blocking visit at 15 6 0 Message successfully applied (result=1)! Received client message (request 5 by player 0) of type with ID=163 (8MoveHero). Player 0 wants to move hero 221 from 15 6 0 to 16 6 0 Sending to all clients a package of type 11TryMoveHero Moved to 16 6 0 Movement end! Message successfully applied (result=1)! Received client message (request 6 by player 0) of type with ID=163 (8MoveHero). Player 0 wants to move hero 221 from 16 6 0 to 17 5 0 Sending to all clients a package of type 11TryMoveHero Moved to 17 5 0 Movement end! Message successfully applied (result=1)! Received client message (request 7 by player 0) of type with ID=163 (8MoveHero). Player 0 wants to move hero 221 from 17 5 0 to 18 5 0 Sending to all clients a package of type 11TryMoveHero Moved to 18 5 0 Movement end! Message successfully applied (result=1)! Received client message (request 8 by player 0) of type with ID=163 (8MoveHero). Player 0 wants to move hero 221 from 18 5 0 to 19 5 0 Sending to all clients a package of type 11TryMoveHero Moved to 19 5 0 Sending to all clients a package of type 9HeroVisit Creating a query for player 0 with ID=1 Sending to all clients a package of type 14BlockingDialog Sending to all clients a package of type 9HeroVisit Movement end! Message successfully applied (result=1)! Received client message (request 9 by player 0) of type with ID=177 (10QueryReply). Creating a query for player 0 with ID=2 Sending to all clients a package of type 14BlockingDialog Message successfully applied (result=1)! Received client message (request 10 by player 0) of type with ID=177 (10QueryReply). Sending to all clients a package of type 17SetObjectProperty Sending to all clients a package of type 15RebalanceStacks Stack of 0 of Centaur Captains #attached to# "Centaur Captains" Stack of 4 of Centaur Captains #attached to# Bonus system node of type 10CGCreature Sending to all clients a package of type 15RebalanceStacks Stack of 0 of Centaur Captains #attached to# "Centaur Captains" Stack of 4 of Centaur Captains #attached to# Bonus system node of type 10CGCreature Sending to all clients a package of type 15RebalanceStacks Stack of 0 of Centaur Captains #attached to# "Centaur Captains" Stack of 5 of Centaur Captains #attached to# Bonus system node of type 10CGCreature Sending to all clients a package of type 15RebalanceStacks Stack of 0 of Centaur Captains #attached to# "Centaur Captains" Stack of 5 of Centaur Captains #attached to# Bonus system node of type 10CGCreature Sending to all clients a package of type 15RebalanceStacks Stack of 0 of Centaur Captains #attached to# "Centaur Captains" Stack of 5 of Centaur Captains #attached to# Bonus system node of type 10CGCreature Sending to all clients a package of type 13PlayerBlocked Sending to all clients a package of type 13PlayerBlocked Message successfully applied (result=1)! VCMI_Client_Log.txt (last part as well): Listening... received server message of type 15RebalanceStacks Made first apply on cl Stack of 0 of Centaur Captains #attached to# "Centaur Captains" Stack of 5 of Centaur Captains #attached to# Bonus system node of type 10CGCreature Applied on gs Made second apply on cl Listening... received server message of type 15RebalanceStacks Made first apply on cl Stack of 0 of Centaur Captains #attached to# "Centaur Captains" Stack of 5 of Centaur Captains #attached to# Bonus system node of type 10CGCreature Applied on gs Made second apply on cl Listening... received server message of type 13PlayerBlocked Made first apply on cl Applied on gs Made second apply on cl Listening... received server message of type 13PlayerBlocked Made first apply on cl Applied on gs Made second apply on cl Listening... received server message of type 14PackageApplied Made first apply on cl Applied on gs Made second apply on cl Listening... Error: server failed to close correctly or crashed! Lost connection to server, ending listening thread! read: End of file Something wrong, lost connection while game is still ongoing... -------------------------------------- PS: What's the difference between vcmi_server.log and VCMI_Server_Log.txt? (Why are there two logs?)

(0003178) Ivan (developer) 2012-10-11 18:00 edited on: 2012-10-11 18:01	Can you upload whole VCMI_Server_Log.txt? There may be some access errors during initialization. VCMI_Server_Log.txt - everything that goes through logging system vcmiserver_log.txt - redirected output from vcmiserver

(0003179) beegee (developer) 2012-10-11 19:18	The error is really disgusting, it happens to appear only sometimes. 2 of 5 tests it crashes when starting a battle. Now I don't know if it depends on the access rights of the /Mods folder:) More tests tomorrow...

(0003180) beegee (developer) 2012-10-12 13:15 edited on: 2012-10-12 13:31	I've uploaded VCMI_Server_Log.txt. This is really confusing: VCMI tag 0.9 release crashes sometimes, while tag 0.9 debug doesn't. Move on with further tests...

(0003181) beegee (developer) 2012-10-12 13:33	Tag 0.9 release in /usr/local crashes too. It seems to be that the crash doesn't appear on debug build on my system. Can it be a race condition(threading)?

(0003182) beegee (developer) 2012-10-12 18:02	I noticed the crash while debugging. In CGameHandler::startBattleI at line 1997 a new thread is created for initializing battle: boost::thread(boost::bind(&CGameHandler::startBattle, this, armies, tile, heroes, creatureBank, cb, town)); Now stop somewhere in CGameState::setupBattle(line 769) execution by a breakpoint. Now switch to the thread which created the upper thread, debug step-by-step forward and you should see a crash message.

(0003183) beegee (developer) 2012-10-19 13:28	Bug fixed in Rev. 2988. After spending a few hours in testing how the crash occured, I've found out that any battle with double-wide creatures lead to the program termination. I wonder why nobody didn't noticed this bug as it's critical. @Ivan: Could you confirm this please? Thanks. The bug was introduced with Rev 2956 from the 29th September. The method AccessibilityInfo::accessible checks whether the tile is accessible for the stack to cover. Before the change there was a check if the hex is valid(0 < x > B_SIZE). This check has been moved after an array access.(which resulted to out_of_index exception) Should I commit this bug fix to tag 0.9 as well? Then we should consider if re-releasing 0.9 is valuable? Otherwise this release seems not to be really playable.

(0003184) Ivan (developer) 2012-10-19 14:29	This is certainly not any battle - no crashes after several battles where both sides have 2-hex creatures. Without your fix of course.

(0003185) beegee (developer) 2012-10-19 15:36	Now this is very strange. Without my fix it seems to crash every battle with 2-hex creatures. With the fix applied it works...

(0003186) beegee (developer) 2012-10-21 16:16 edited on: 2012-10-21 16:21	Finally I've found out why the mysterious crash occurs. The const method at(size_type n) of the std:array struct in the gcc implementation contains a bug. (The first bug which I found in a compiler or std lib...^^) This is the affected method: http://en.cppreference.com/w/cpp/container/array/at [^] There exists a thread about that bug on StackOverflow here: http://stackoverflow.com/questions/12136394/issue-with-bounds-checking-a-member-stdarray-inside-a-const-function [^] Here the bug report on the bug tracker database of GCC: http://gcc.gnu.org/bugzilla/show_bug.cgi?id=54388 [^] The bug was fixed on the 9th September 2012. The newly released GCC 4.7.2 contains that bugfix. This means there was no problem with the vcmi server/lib code. In debug versions of VCMI better said if VCMI has been compiled with -O0 or no optimization at all, the bug didn't appear. Otherwise with a release build the at(...) method returned random numbers. (they could lead to a crash, or not) Should we refactor the code to use the unchecked []-operator which works(it can be troublesome to find all references...) or suggest that devs/users should update to GCC 4.7.2?

(0003187) Tow (developer) 2012-10-22 19:07	The bug apparently affects only the 4.7 series and my understanding is that all Linux distribution should update GCC to 4.7.2 (if they do have GCC 4.7 at all). So I believe this issue should not affect many developers. My suggestion would be to leave the code as but add some kind of diagnostic (pseudocode): #if GCC 4.7.0 \|\| GCC 4.7.1 #error This GCC version has buggy std::array::at version and should not be used. Please update to 4.7.2 or use 4.6.x. #endif Alternative: * replace std::array with boost::array — less cumbersome than forbidding calling array::at().

(0003188) beegee (developer) 2012-10-24 15:32	Fixed in Rev. 2992

Issue History
Date Modified	Username	Field	Change
2012-10-11 17:01	beegee	New Issue
2012-10-11 17:33	Ivan	Note Added: 0003176
2012-10-11 17:57	Ivan	Note Edited: 0003176	View Revisions
2012-10-11 17:58	beegee	Note Added: 0003177
2012-10-11 17:59	Ivan	Note Edited: 0003176	View Revisions
2012-10-11 17:59	beegee	Note Edited: 0003177	View Revisions
2012-10-11 18:00	Ivan	Note Added: 0003178
2012-10-11 18:01	Ivan	Note Edited: 0003178	View Revisions
2012-10-11 19:18	beegee	Note Added: 0003179
2012-10-12 12:39	beegee	File Added: VCMI_Server_log.txt
2012-10-12 13:15	beegee	Note Added: 0003180
2012-10-12 13:31	beegee	Note Edited: 0003180	View Revisions
2012-10-12 13:33	beegee	Note Added: 0003181
2012-10-12 18:02	beegee	Note Added: 0003182
2012-10-19 13:28	beegee	Note Added: 0003183
2012-10-19 14:29	Ivan	Note Added: 0003184
2012-10-19 15:36	beegee	Note Added: 0003185
2012-10-21 16:16	beegee	Note Added: 0003186
2012-10-21 16:21	beegee	Note Edited: 0003186	View Revisions
2012-10-22 19:07	Tow	Note Added: 0003187
2012-10-24 15:32	beegee	Note Added: 0003188
2012-10-24 15:32	beegee	Status	new => resolved
2012-10-24 15:32	beegee	Fixed in Version	=> 0.91
2012-10-24 15:32	beegee	Resolution	open => fixed
2012-10-24 15:32	beegee	Assigned To	=> beegee
2014-05-30 17:41	beegee	Status	resolved => closed

Relationships