Identifying and solving OOS problems

[Alrik2002]

Hi,

I would like to check my mixed mod for OOS-Errors. For this I´ve some general questions.

1. I know, that there is a MPLog, which you can activate. While the game is running, it´s in the logs-folder but when I´ve quit the game, it´s gone. Could you tell me how I can "hold" it, so that I can check it later?

2. In the MPLog I´ve found some ASYNC Rand numbers already:

• AI Best UnitAI
• AI Best BuildingAI
• Pick Song
• AI Best Unit
• Wonder Construction Rand

I´ve seen that these names are defined in the CyGame().getSorenRandNum. But how do I find the specific .py-file, where it´s used?

3. Since you can´t use the worlbuilder in MP-games, how do you test if a game will get OOS on a specific function?

Thanks so far. I believe I will have several more questions later, when I start testing.

 

[Alrik2002]

Really. No one?

 

[AIAndy]

I usually use OOSLogger.py to write some OOS log when it happens.
That can be compared between players to find in what way the game state differs.

Also if you switch on random logging you should get random logs in your Logs folder which should show at what point the RNG started to differ between the computers and then you can use a search program to find in what files the phrase passed to getSorenRandNum is used.

Testing in general is difficult in MP.

 

[Alrik2002]

Hi AIAndy,

which search program would you recommend?

OOSLogger.py? This is not in the BtS-Standard right?

 

[AIAndy]

Hi AIAndy,

which search program would you recommend?

I currently use Windows Grep to search through the files:
http://www.wingrep.com/download.htm

OOSLogger.py? This is not in the BtS-Standard right?

No, I think not. It was already in the C2C code when I started modding (probably inherited from RoM). So I can't even say who originally wrote it.

https://caveman2cosmos.svn.sourceforge.net/svnroot/caveman2cosmos/trunk/Assets/Python/OOSLogger.py
When doGameUpdate runs every game update it will catch an OOS soon after it happens and then writes a log on each computer with the information that is actually used to compute the sync checksum.

 

[Alrik2002]

Great. Thanks.

 

[Alrik2002]

The program for the search works fine. I found out, that all of the following are part of the dll.

The log is one of a just started single player game, so I wonder, if these messages are important and should be solved or if they are normal like that although they are shown as ASYNC (but compared to what since it´s single player ).

Rand = -708200964 on 91 (Pick Song ASYNC)
Rand = -650237496 on 105 (AI Strategy Rand)
Rand = 1404852320 on 115 (AI Best UnitAI ASYNC)
Rand = -1000402663 on 115 (AI Best Unit ASYNC)
Rand = 637933022 on 115 (AI Best UnitAI ASYNC)
Rand = 1391797183 on 115 (AI Best UnitAI ASYNC)
Rand = 670997132 on 115 (AI Best UnitAI ASYNC)
Rand = -1362713131 on 115 (AI Best UnitAI ASYNC)
Rand = 1222226410 on 115 (AI Best UnitAI ASYNC)
Rand = 1575107803 on 115 (AI Best UnitAI ASYNC)
Rand = -1807690888 on 115 (AI Best UnitAI ASYNC)
Rand = -422000047 on 115 (AI Best UnitAI ASYNC)
Rand = 1670972086 on 115 (AI Best UnitAI ASYNC)
Rand = 1438501815 on 115 (AI Best Building ASYNC)
Rand = 1550561060 on 115 (AI Best Building ASYNC)
Rand = -1022444915 on 115 (Wonder Construction Rand ASYNC)
Rand = -1607822270 on 115 (AI Best Building ASYNC)

 

[AIAndy]

Which log is that?

For random logging activate the random log in the Civ ini and then check the RandomLogger files in the Logs folder.

 

[Alrik2002]

It´s called MPLog and activated by

; Enable synchronization logging
SynchLog = 1

I believe.

Do you mean the following part in the ini?

; Random seed for game sync, or '0' for default
SyncRandSeed = 0

 

[God-Emperor]

In a bunch of places the code knows if it is in multiplayer or not and if not it uses a different random number generator. For example, several messages from the log were "AI Best UnitAI ASYNC". If you search all the source code for that string, you'll find that this comes from this code in CvCityAI::AI_bestUnit

			if (bAsync)
			{
				aiUnitAIVal[iI] += GC.getASyncRand().get(iMilitaryWeight, "AI Best UnitAI ASYNC");
			}
			else
			{
				aiUnitAIVal[iI] += GC.getGameINLINE().getSorenRandNum(iMilitaryWeight, "AI Best UnitAI");
			}

So "bAsync" was true. If it had been false, it would have used the MP synchronized getSorenRandNum. I think you'll find it is true in single player and false in multiplayer. Or, at least, it is supposed to be. If you added code that calls this function with the wrong setting for the bAsync argument then that has a good chance of causing an OOS situation since it would use the unsynchronized RNG (which may or may not give the same results on the different computers running the game).

Code like this makes it even harder to debug multiplayer issues since when you are not running multiplayer it doesn't even run the same code everywhere.

 

[AIAndy]

In a bunch of places the code knows if it is in multiplayer or not and if not it uses a different random number generator. For example, several messages from the log were "AI Best UnitAI ASYNC". If you search all the source code for that string, you'll find that this comes from this code in CvCityAI::AI_bestUnit

			if (bAsync)
			{
				aiUnitAIVal[iI] += GC.getASyncRand().get(iMilitaryWeight, "AI Best UnitAI ASYNC");
			}
			else
			{
				aiUnitAIVal[iI] += GC.getGameINLINE().getSorenRandNum(iMilitaryWeight, "AI Best UnitAI");
			}

So "bAsync" was true. If it had been false, it would have used the MP synchronized getSorenRandNum. I think you'll find it is true in single player and false in multiplayer. Or, at least, it is supposed to be. If you added code that calls this function with the wrong setting for the bAsync argument then that has a good chance of causing an OOS situation since it would use the unsynchronized RNG (which may or may not give the same results on the different computers running the game).

Code like this makes it even harder to debug multiplayer issues since when you are not running multiplayer it doesn't even run the same code everywhere.

Actually as far as I know most of the occurances of that kind of code are when a certain function can be used both in sync and in async context.
For instance when you want to give the player a recommendation of what to build on an UI screen then you'd need to use the async RNG because that part will only run on the computer that displays the screen.

@Alrik: I have to admit that I have not used the MPLog up to now but the random log activated with this in the ini:
; Enable rand event logging
RandLog = 1

 

[God-Emperor]

Actually as far as I know most of the occurances of that kind of code are when a certain function can be used both in sync and in async context.
For instance when you want to give the player a recommendation of what to build on an UI screen then you'd need to use the async RNG because that part will only run on the computer that displays the screen.

Interesting. It turns out that you are right. It looks like that particular function is only called in 2 places and the one that uses the async RNG is doing a pop-up for the human. At some point I guess I just assumed these things were for MP vs. single player usage and never checked. Oops.

 

[Alrik2002]

@Alrik: I have to admit that I have not used the MPLog up to now but the random log activated with this in the ini:
; Enable rand event logging
RandLog = 1

OK. This I´ve turned on too. I´ve to see if I have a RandomLogger after my next MP-test. Do you use the Checksum-log too for debugging? I could imagine to compare these with winmerge after an oos had occured to see what´s different.

So the I could assume, that the posted parts should be ok for MP because there is a reason to run these async?

Btw. what is an UI Screen?

 

[AIAndy]

OK. This I´ve turned on too. I´ve to see if I have a RandomLogger after my next MP-test. Do you use the Checksum-log too for debugging? I could imagine to compare these with winmerge after an oos had occured to see what´s different.

Currently I only use the OOS log from OOSLogger.py to find out what is different and if the soren rand is different in there I use the RandomLogger to find out when the rands started to be different.

So the I could assume, that the posted parts should be ok for MP because there is a reason to run these async?

Possibly, but it depends on the details.

Btw. what is an UI Screen?

UI = User Interface

 

[Alrik2002]

Ok. I´ve tried to implement the OOSLogger in my mod but unfortunatly without success.

What I´ve done:
1. Copy the OOSLogger.py in my python-folder.
2. Edit my CvEventManager.py:

import OOSLogger

and

	def onGameUpdate(self, argsList):
		'sample generic event, called on each game turn slice'
		genericArgs = argsList[0][0]	# tuple of tuple of my args
[COLOR="Red"]##OOSLogger Start ##
		OOSLogger.doGameUpdate()
##OOSLogger Ende ##
#[/COLOR]		turnSlice = genericArgs[0]

Then I provoked an OOS but the logfile wasn´t written. I´ve searched for other places where ooslogger should be imported or something like that, but I didn´t find anything.

Rand Event Logging is enabled on both computers.

Do you have any idea what I´m missing or making wrong?

 

[AIAndy]

Ok. I´ve tried to implement the OOSLogger in my mod but unfortunatly without success.

What I´ve done:
1. Copy the OOSLogger.py in my python-folder.
2. Edit my CvEventManager.py:

import OOSLogger

and

	def onGameUpdate(self, argsList):
		'sample generic event, called on each game turn slice'
		genericArgs = argsList[0][0]	# tuple of tuple of my args
[COLOR="Red"]##OOSLogger Start ##
		OOSLogger.doGameUpdate()
##OOSLogger Ende ##
#[/COLOR]		turnSlice = genericArgs[0]

Then I provoked an OOS but the logfile wasn´t written. I´ve searched for other places where ooslogger should be imported or something like that, but I didn´t find anything.

Rand Event Logging is enabled on both computers.

Do you have any idea what I´m missing or making wrong?

By default the OOS log ends up in the folder with the BeyondTheSword exe which also means that it needs write access to there.

 

[Alrik2002]

Is it possible to change it that the log is written in the logs-folder?

 

[AIAndy]

Is it possible to change it that the log is written in the logs-folder?

Yes, you would need to find the proper directory for the Logs folder though and add it before the szNewFilename in OOSLogger.py.
If you use BUG, then you can use the code in there for finding the user directory (I guess you can also just copy it if you don't use BUG). It is in BugPath.py and can be retrieved with getUserDir or getRootDir.
That reminds me that I should probably change the OOSLogger.py in C2C in a similar way.

 

[Alrik2002]

Ok. I use BUG, so I´ve only to add "getUserDir()" at the correct point? Sorry but where exactly?

I´ve tried several positions, but it didn´t wrote any log. There are several positions where szNewFilename is used.

from CvPythonExtensions import *
import CvUtil

gc = CyGlobalContext()

[COLOR="Red"]szFilename[/COLOR] = "OOSLog.txt"
iMaxFilenameTries = 100

bWroteLog = False

SEPERATOR = "-----------------------------------------------------------------\n"


# Simply checks every game turn for OOS. If it finds it, writes the
# info contained in the sync checksum to a log file, then sets the bWroteLog
# variable so that it only happens once.
def doGameUpdate():
	global bWroteLog
	bOOS = CyInterface().isOOSVisible()

	if (bOOS and not bWroteLog):
		writeLog()
		bWroteLog = True

def writeLog():
	playername = CvUtil.convertToStr(gc.getPlayer(gc.getGame().getActivePlayer()).getName())
	[COLOR="Red"]szNewFilename[/COLOR] = "%s - Player %s - " % (playername, gc.getGame().getActivePlayer()) + "OOSLog - Turn " + "%s" % (gc.getGame().getGameTurn()) + ".txt"
	pFile = open([COLOR="Red"]szNewFilename[/COLOR], "w")

Do I have to import BugPath in the OOSLogger?

Sorry for all these questions.

 

[AIAndy]

Ok. I use BUG, so I´ve only to add "getUserDir()" at the correct point? Sorry but where exactly?

I´ve tried several positions, but it didn´t wrote any log. There are several positions where szNewFilename is used.

from CvPythonExtensions import *
import CvUtil

gc = CyGlobalContext()

[COLOR="Red"]szFilename[/COLOR] = "OOSLog.txt"
iMaxFilenameTries = 100

bWroteLog = False

SEPERATOR = "-----------------------------------------------------------------\n"


# Simply checks every game turn for OOS. If it finds it, writes the
# info contained in the sync checksum to a log file, then sets the bWroteLog
# variable so that it only happens once.
def doGameUpdate():
	global bWroteLog
	bOOS = CyInterface().isOOSVisible()

	if (bOOS and not bWroteLog):
		writeLog()
		bWroteLog = True

def writeLog():
	playername = CvUtil.convertToStr(gc.getPlayer(gc.getGame().getActivePlayer()).getName())
	[COLOR="Red"]szNewFilename[/COLOR] = "%s - Player %s - " % (playername, gc.getGame().getActivePlayer()) + "OOSLog - Turn " + "%s" % (gc.getGame().getGameTurn()) + ".txt"
	pFile = open([COLOR="Red"]szNewFilename[/COLOR], "w")

Do I have to import BugPath in the OOSLogger?

Sorry for all these questions.

Yes, I assume you have to import it.
And then the important line is the one where the file name is generated:
szNewFilename = "%s - Player %s - " % (playername, gc.getGame().getActivePlayer()) + "OOSLog - Turn " + "%s" % (gc.getGame().getGameTurn()) + ".txt"
In that you have to add the directory in front (I think getRootDir() + "\\Logs\\" + the rest that is already there).