[fixed]3.8.0-beta1 OOS when playing windows/linux and using egypt

[titi]

Today I had the third OOS with a human playing egypt. So far i never saw this with a egypt AI player, so it must be something that humans do. Its always the egypt faction which gets OOS.
Sadly I cannot give more details yet , just the fact that it looks like this bug sometimes causes crashes too ( https://forum.megaglest.org/index.php?topic=9165.0 ).

I know I need to get more details, I just want to mention that there still must be a OOS :-( .

[filux]

From my observations that it is quite rare and regardless of faction.
The only thing repeated in the error messages is: problem with "isCancelPreMorphCommand".
For a very long time I haven't seen any OOS which aren't related with this command.

e.g. https://forum.megaglest.org/index.php?topic=9110.0

[titi]

YOu are right    its not only egypt, it happens with other factions too. I had one more OOS today without egypt. I hope I will find the time on weekend to let the computers play vs each other. Only problem is we still have a bug in the OOS sync logging itself :-/ .

Update: and one more OOS game :-(

[softcoder]

Ok please setup host and clients with world synch logging then provide the logs after getting OOS. MAke sure to quit and restart the game if a previous game plays successful.

[titi]

I tried a lot now, but I had no luck. Currently its logging much too much and this takes so much time that the client ( windows laptop ) always dropps out, because it falls back too much.

Is there any way to reduce the the things we log ?
Currently I get  for exmaple 4,6 GB for just some minutes of playing ( when second attack wave of playing AIs starts ).

Like this I cannot log the error, 

update:
A different idea how to find/log out of sync problems:  What about only calculating the CRCs for states on server and client instead of logging all. These CRCs are send to server and client. Once they are different we start to log on servers and clients.
By this we only log if things are different.
A problem is that we don't see which "commands" caused these problems,  If those are needed, Maybe a cyclic logging to memory for the last 50 frames or so helps. This is written to the logfile once we see that there is trouble.

[filux]

Another to collection.
I received it close to the end of the game hosted by Carla.

Code: [Select]

[] *ERROR* In [commander.cpp::buildCommand Line: 997]
Can not find command type for network command = [networkCommandType = 0
unitId = 500448
commandTypeId = 3
positionX = 73
positionY = 176
unitTypeId = 18
targetId = 0
wantQueue= 0
fromFactionIndex = 0
unitFactionUnitCount = 101
unitFactionIndex = 5, commandStateType = 0, commandStateValue = -1, unitCommandGroupId = -1]
Commands:  id = 0 id = 1 id = 2
for unit = 500448
[axe_thrower]
[
HP: 0/700
Armor: 20+5 (leather)
Sight: 12
Kills: 1]
actual local factionIndex = 5.
Unit Type Info:
[Unit Name: [axe_thrower] id = 2 maxHp = 700 hpRegeneration = 0 maxEp = 0 epRegeneration = 0 maxUnitCount = 0 fields index = 0 value = 1 fields index = 1 value = 0 properties index = 0 value = 0 properties index = 1 value = 0 armor = 20 armorType Name: [leather id = 1 light = 0 lightColor = x [0] y [0] z [0] multiSelect = 1 sight = 12 size = 1 height = 2 rotatedBuildPos = 0.0000000000000000 rotationAllowed = 1 skillTypes: [5] i = 0 Stop i = 1 Move i = 2 Attack i = 3 Morph i = 4 Die commandTypes: [3] i = 0 Stop i = 1 Move i = 2 Attack storedResources: [0] levels: [0] meetingPoint = 0 countInVictoryConditions = 0]
Network unit type:
[thunderbird]
isCancelPreMorphCommand: 0
Game out of synch.
[] *ERROR* In [game.cpp::update Line: 2671] Error [Error [#3]: Game is out of sync, please check log files for details.
Stack Trace:
./megaglest:Shared::Platform::megaglest_runtime_error::megaglest_runtime_error(std::string const&, bool)address [0xa20222] line: 237
./megaglest:Glest::Game::Commander::buildCommand(Glest::Game::NetworkCommand const*) constaddress [0x583851] line: 1014
./megaglest:Glest::Game::Commander::giveNetworkCommand(Glest::Game::NetworkCommand*) constaddress [0x585d6e] line: 863
./megaglest:Glest::Game::Commander::updateNetwork(Glest::Game::Game*)address [0x589acb] line: 548
./megaglest:Glest::Game::Game::update()address [0x5c98e0] line: 2147
./megaglest:Glest::Game::Program::loopWorker()address [0x6b9c71] line: 459
./megaglest:Glest::Game::glestMain(int, char**)address [0x6a9510] line: 5379
./megaglest:Glest::Game::glestMainSEHWrapper(int, char**)address [0x6ac226] line: 5626
/lib64/libc.so.6:__libc_start_main()address [0x7f5912199455] line: 0
./megaglest() [0x515a89]address [0x515a89]

[tomreyn]

I had this happen again today. I was hosting on Linux on atibox, several clients with mixed Linux / Windows were connected, and we went OOS. I had not set any special settings, notably I had not activated techtree translation. What I did have set was Desert4, so a tileset using the new tileset features.

[titi]

Current state: Softcoder added a CRC check in the code now who instantly finds any kind of difference between client and server. Also it still does not work perfect it already helped to find another bug that caused OOS before.
Whats needed now are more play tests ( crossplatform windows/linux ) so we know where we stand. Yesterday we already had a bigger game and no problems showed up also I used egypt faction which typically shows this Problem very good . So if you have time, get the executable from here:( https://forum.megaglest.org/index.php?topic=8753.0 ) or compile for yourself and help testing.

Then report back all you have ! Success or no success, all is needed ( just regarding Out Of Sync of course )

[tomreyn]

We played two more full (start to end) x-platform games last night on r4547 (and higher) with Egypt and couldn't reproduce OOS either.

One of these games involved using the fixed (r4548) CRC checks. We did not run into any mismatch (great!) but generally the checks are too slow to keep them enabled for a full game (especially but not only Windows users will time out due to the computational overhead), it makes the game really hard to play and impossible to enjoy. But then, we're just testing - and don't get me wrong: it's great that we have this optional feature available.

[softcoder]

Let me know if this is reproducible.

[tomreyn]

Lyra (Windows 7-64, client) and I (Ubuntu 13.04 x86_64) played three games with all Egypt (2 humans vs. 2 Ultra CPU, 4.9x) and lots of splash. The first two games there was no CRC checksum mismatch, but there was on the last game. I've uploaded the combined logs. It happened many minutes into the game, and lyra got disconnected with an error message (the server only witnessed what looked like a voluntary disconnect) and I stopped the game shortly after.

[titi]

and one more game of Lyra and me which ended with a CRC:

Here are the logs:
Me host ( linux ): http://titi.megaglest.org/server.7z
Lyra client WIndows:  http://www.sendspace.com/file/ejkwo5

[tomreyn]

Lyra and I just played again, r4571 this time, but with a similar setup as before. Her Windows client lagged quite a bit again due to checksumming and Intel graphics, and we ran into a CRC mismatch. My (server) logs are uploaded here. Lyra's (client) logs are uploaded there. Her cmd said this, mine said that:

Code: [Select]

megaglest v3.8.0-dev
Compiled using: GNUC: 40703 [64bit] on: Sep 25 2013 03:00:50 platform: Linux-X64 endianness: little
SVN: [Rev: 4571M] - using STREFLOP [SSE] - [no-denormals]
radeon: Acquired access to Hyper-Z.
[] *ERROR* SOCKET WRITE TIMEOUT In [/home/user1/SCM/megaglest-trunk/source/shared_lib/sources/platform/posix/socket.cpp::isWritable Line: 1756] i = 0 sock = 16
[] *ERROR* SOCKET WRITE TIMEOUT In [/home/user1/SCM/megaglest-trunk/source/shared_lib/sources/platform/posix/socket.cpp::isWritable Line: 1756] i = 0 sock = 16
[] *ERROR* SOCKET WRITE TIMEOUT In [/home/user1/SCM/megaglest-trunk/source/shared_lib/sources/platform/posix/socket.cpp::isWritable Line: 1756] i = 0 sock = 16
*Note: Monitoring Network CRC NORMAL synchronization...
*TESTING*: START Waiting for lagging client playerIndex = 0 [lyra] clientLagCount = 11.000000 [0.000000]
*TESTING*: FINISHED Waiting for lagging client playerIndex = 0 [lyra]
*TESTING*: START Waiting for lagging client playerIndex = 0 [lyra] clientLagCount = 11.000000 [0.000000]
*TESTING*: FINISHED Waiting for lagging client playerIndex = 0 [lyra]
*TESTING*: START Waiting for lagging client playerIndex = 0 [lyra] clientLagCount = 11.000000 [0.000000]
*TESTING*: FINISHED Waiting for lagging client playerIndex = 0 [lyra]
*TESTING*: START Waiting for lagging client playerIndex = 0 [lyra] clientLagCount = 11.000000 [0.000000]
*TESTING*: FINISHED Waiting for lagging client playerIndex = 0 [lyra]
*TESTING*: START Waiting for lagging client playerIndex = 0 [lyra] clientLagCount = 11.000000 [0.000000]
*TESTING*: FINISHED Waiting for lagging client playerIndex = 0 [lyra]
*TESTING*: START Waiting for lagging client playerIndex = 0 [lyra] clientLagCount = 11.000000 [0.000000]
*TESTING*: FINISHED Waiting for lagging client playerIndex = 0 [lyra]
*TESTING*: START Waiting for lagging client playerIndex = 0 [lyra] clientLagCount = 11.000000 [0.000000]
*TESTING*: FINISHED Waiting for lagging client playerIndex = 0 [lyra]
*TESTING*: START Waiting for lagging client playerIndex = 0 [lyra] clientLagCount = 11.000000 [0.000000]
*TESTING*: FINISHED Waiting for lagging client playerIndex = 0 [lyra]
*TESTING*: START Waiting for lagging client playerIndex = 0 [lyra] clientLagCount = 11.000000 [0.000000]
*TESTING*: FINISHED Waiting for lagging client playerIndex = 0 [lyra]
Check save world CRC to log. isNetworkGame = 1 fileSuffix = _faction_0
Save to log debugCRCWorldLogFile = /home/user1/.megaglest/debugCRCWorld.log_faction_0
Check save world CRC to log. isNetworkGame = 1 fileSuffix = _server
Save to log debugCRCWorldLogFile = /home/user1/.megaglest/debugCRCWorld.log_server
Check save world CRC to log. isNetworkGame = 1 fileSuffix = _client
Save to log debugCRCWorldLogFile = /home/user1/.megaglest/debugCRCWorld.log_client
Check save world CRC to log. isNetworkGame = 1 fileSuffix = _client
Save to log debugCRCWorldLogFile = /home/user1/.megaglest/debugCRCWorld.log_client
radeon: Released access to Hyper-Z.

[titi]

rev 4572:

2 player game:

lyra windows client: http://www.sendspace.com/file/4386um

titi linux 64 server: http://titi.megaglest.org/server2.7z

[tomreyn]

Another game on r4572 with CRC mismatch. I was hosting (atibox), Titi was the Windows client, Atze (Linux 64) joined us.

Server logs
Titi's client logs
Atzes' client logs

[titi]

rev 4574:
4 player cross platform game game:
we only have logs of 2 clients and the server:

Atze server linux: http://s000.tinyupload.com/?file_id=02890039838876336676
titi client windows:  http://titi.megaglest.org/debugCRCWorld.log_win_client.7z
lyra linux client: http://www.sendspace.com/file/3y8f7z
derek windows: log is missing, but got CRC in the same moment as I got it.

[softcoder]

Try svn as I have committed additional fixes.

Thanks

[tomreyn]

Thanks.

Lyra (W-7-64 client) and I (atibox) just tried r4575, but ran into another checksum mismatch. Rather quickly actually, but I set my game to German language, so this could be why.

My (server) logs

Lyra's logs, Lyra's terminal output

[ctz]

A CRC error occurred on r4576 with tomreyn as the host, I (lyra) the client, same machines as last time (above post).
This error happened with the same settings as last time and a similar situation, with tomreyn walking a mummy to the opposing teams' area to provoke them and leading them around to fight each other.

tomreyn's server logs: http://tomreyn.megaglest.org/debugCRCWorld_tomreyn_20130927_2.tar.xz
my client log: http://www.sendspace.com/file/os3yni and terminal output: http://pastebin.com/raw.php?i=LvY27g2A

[tomreyn]

Today, Titi (Windows 7-64, I think) was running the client which connected to my (atibox) server, both running r4577.
It took us quite a while to go OOS, pleaying a very similar game (same settings) to the one lyra / ctz and I played yesterday.

My log
Titi's log

[titi]

Lyra me and tomreyn teste rev 4583:

You nearly instantly get a CRC error now if  someone uses attack particles on the map. Lyra attacled his own worker with the Egypt Priest. 1 second later we got a CRC error.
We tried it again with same result.

Here are the logfiles for our first try:

<lyra`> http://www.sendspace.com/file/4tjivo    ( linux client )
<tomreyn> http://tomreyn.megaglest.org/debugCRCWorld_tomreyn_20130930_1.tar.xz  (  linux server )
<titi_linux> http://titi.megaglest.org/debugCRCWorld.log_client_windows.7z ( windows client )

[ctz]

Correction to titi's report above:
I attacked my spearthrower with the priest, and had a spearman in the splash radius.  Then I moved the priest to stop the attack, and a few seconds later titi got disconnected by CRC error.

[tomreyn]

Nig and I just had a CRC mismatch on r4589, windows 7-64 host (nig), linux-64 client (tomreyn on atibox).

client logs: http://tomreyn.megaglest.org/debugCRCWorld_tomreyn_20131003_1.tar.xz
server logs: http://www.fastshare.org/download/lo..7z

Code: (Client terminal output) [Select]

X**X Frame: 7840 faction: 1 local CRC: 4081333890 Remote CRC: 180790778

[tomreyn]

Now.. this may actually be fixed on r4592!

We played 2 cross-platform games (both hosted on atibox - it would be good to also host some on Windows), one with all Egypt and loads of splash, the other with mixed factions (but still Megapack) and plenty of fights (also including splash). Lyra lagged got disconnected both times even though I had the "wait for lagging player" option on, and there were no warnings ever, it just said she had disconnected.

[tomreyn]

This has now less to do with the original topic of this thread (not about Egypt), but since the underlying issue is still related, I'll keep it here.

Lyra (Windows 64 bit client) and I (atibox hosting) were playing a game against each other on r4596. I think we never did this test scenario since checksumming was introduced.

Lyra was with a 1.5 Ultra bot, I was alone on the other side (and team), and Lyra experienced a checksum mismatch during the first larger attack. She also said she experienced a few pauses (followed by rapid catching-up) during this game, likely due to network interference.

My (server) log file (and terminal output)

Lyra's terminal output
Lyra's log file

Edit: Added revision #