Interpreting the MPLog and Finding the causes of OOS's

[Afforess]

I've gotten scattered reports that my mod has issues with Multiplayer, which isn't surpising, given the quality of my code sometimes...

I have one player who is giving me two copies of their MPLog.log files, which show the rand number info for each player, and are quite revealing in Winmerge, it's very obvious when things go ary. However, I'm, at a complete loss as how to interprete the information and correct the bug(s).

Here are the aforementioned logs.
View attachment MP Testing.rar

Has anyone else done Multiplayer debugging, and know how to do it? I wouldn't even know the first thing to do...

 

[EmperorFool]

From what I understand there are two random number generators: one that needs to be used in exactly the same sequence on each machine, and another that does not (asynchronous). All of those ASYNC messages are this latter sequence and do not matter.

The first non-asynch mismatch I see is in player 2's log:

Rand = -411323862 on 3147 (Bonus Depletion)

Search your code for "Bonus Depletion". This is the comment that you pass to getSorenRandNum or whatever it's called. Whatever makes this call happen is not being run on every machine. If the trigger doesn't happen on everyone's machine, the machine that triggers it must send a net message to the others to make it happen.

For example, let's say that every turn in a two player game the odd or even (alternating) player gets to choose whether or not to give both players a random amount of gold. If a player is very far ahead, they might not want to give their opponent a chance to catch up, so they would say no.

If you do this

onBeginPlayerTurn
    if player # % turn # == 0 (even/odd check)
        popup: want to give gold?
        if yes:
            give rand() gold to player 0
            give rand() gold to player 1

The problem is that those two calls to rand() only run on the machine of the player that got the popup. Instead you need to send a message after the player says "yes":

onBeginPlayerTurn
    if player # % turn # == 0 (even/odd check)
        popup: want to give gold?
        if yes:
            send message

onModNetMessage
    if is gold message
        give rand() gold to player 0
        give rand() gold to player 1

 

[davidlallen]

You may have read the two recent threads on this, and you may have read the MP Guide; if not, I recommend those.

 

[Afforess]

I noticed the bonus depletion thing too, but the odd part is that this is in the SDK, and is run right after the code that randomly spawns new resources on mines.

See, look here:

void CvPlot::doImprovement()
{
	PROFILE_FUNC();

	CvCity* pCity;
	CvWString szBuffer;
	int iI;

	FAssert(isBeingWorked() && isOwned());

	if (getImprovementType() != NO_IMPROVEMENT)
	{
		if (getBonusType() == NO_BONUS)
		{
			FAssertMsg((0 < GC.getNumBonusInfos()), "GC.getNumBonusInfos() is not greater than zero but an array is being allocated in CvPlot::doImprovement");
			for (iI = 0; iI < GC.getNumBonusInfos(); ++iI)
			{
				if (GET_TEAM(getTeam()).isHasTech((TechTypes)(GC.getBonusInfo((BonusTypes) iI).getTechReveal())))
				{
/************************************************************************************************/
/* UNOFFICIAL_PATCH                       10/22/09                                jdog5000      */
/*                                                                                              */
/* Gamespeed scaling                                                                            */
/************************************************************************************************/
/* original bts code
					if (GC.getImprovementInfo(getImprovementType()).getImprovementBonusDiscoverRand(iI) > 0)
					{
						if (GC.getGameINLINE().getSorenRandNum(GC.getImprovementInfo(getImprovementType()).getImprovementBonusDiscoverRand(iI), "Bonus Discovery") == 0)
						{
*/
					int iOdds = GC.getImprovementInfo(getImprovementType()).getImprovementBonusDiscoverRand(iI);
					iOdds *= GC.getGameSpeedInfo(GC.getGameINLINE().getGameSpeedType()).getResearchPercent();
					iOdds /= 100;

					if( iOdds > 0 )
					{
						if( GC.getGameINLINE().getSorenRandNum(iOdds, "Bonus Discovery") == 0)
						{
/************************************************************************************************/
/* UNOFFICIAL_PATCH                        END                                                  */
/************************************************************************************************/
							setBonusType((BonusTypes)iI);

							pCity = GC.getMapINLINE().findCity(getX_INLINE(), getY_INLINE(), getOwnerINLINE(), NO_TEAM, false);

							if (pCity != NULL)
							{
								szBuffer = gDLL->getText("TXT_KEY_MISC_DISCOVERED_NEW_RESOURCE", GC.getBonusInfo((BonusTypes) iI).getTextKeyWide(), pCity->getNameKey());
								gDLL->getInterfaceIFace()->addMessage(getOwnerINLINE(), false, GC.getEVENT_MESSAGE_TIME(), szBuffer, "AS2D_DISCOVERBONUS", MESSAGE_TYPE_MINOR_EVENT, GC.getBonusInfo((BonusTypes) iI).getButton(), (ColorTypes)GC.getInfoTypeForString("COLOR_WHITE"), getX_INLINE(), getY_INLINE(), true, true);
							}

							break;
						}
					}
				}
			}
		}
/************************************************************************************************/
/* Afforess	                  Start		 01/20/10                                               */
/*                                                                                              */
/*   Mine Depletion                                                                             */
/************************************************************************************************/
		if (GC.isCanDeplete())
		{
			bool bObstruction = ((getBonusType(getTeam()) != NO_BONUS) && (GC.getImprovementInfo(getImprovementType()).isImprovementBonusMakesValid(getBonusType(getTeam()))));

			if (!bObstruction)
			{
				int iDepletionOdds = GC.getImprovementInfo(getImprovementType()).getDepletionRand();
				iDepletionOdds *= GC.getGameSpeedInfo(GC.getGameINLINE().getGameSpeedType()).getResearchPercent();
				iDepletionOdds /= 100;
				ImprovementTypes eDepletedMine;
				eDepletedMine = findDepletedMine();
				
				if( iDepletionOdds > 0 )
				{
					if (eDepletedMine != NO_IMPROVEMENT)
					{
						if( GC.getGameINLINE().getSorenRandNum(iDepletionOdds, "Mine Depletion") == 0)
						{
							szBuffer = gDLL->getText("TXT_KEY_MISC_IMPROVEMENT_DEPLETED", GC.getImprovementInfo(getImprovementType()).getDescription());
							gDLL->getInterfaceIFace()->addMessage(getOwnerINLINE(), false, GC.getEVENT_MESSAGE_TIME(), szBuffer, "AS2D_FIRSTTOTECH", MESSAGE_TYPE_MINOR_EVENT, GC.getImprovementInfo(getImprovementType()).getButton(), (ColorTypes)GC.getInfoTypeForString("COLOR_RED"), getX_INLINE(), getY_INLINE(), true, true);
							setImprovementType(eDepletedMine);
							setIsDepletedMine(true);
							pCity = GC.getMapINLINE().findCity(getX_INLINE(), getY_INLINE(), getOwnerINLINE(), NO_TEAM, false);
							GC.getGameINLINE().logMsg("Mine Depleted!");
							if (pCity != NULL)
							{	
								pCity->AI_setAssignWorkDirty(true);
							}
						}
					}
				}
			}
			//Resource Depletion
			else
			{
				if (GET_TEAM(getTeam()).isHasTech((TechTypes)(GC.getBonusInfo(getBonusType()).getTechReveal())))
				{
					int iBonusOdds = GC.getImprovementInfo(getImprovementType()).getImprovementBonusDepletionRand(getBonusType());
					iBonusOdds *= GC.getGameSpeedInfo(GC.getGameINLINE().getGameSpeedType()).getResearchPercent();
					iBonusOdds /= 100;

					if( iBonusOdds > 0 )
					{
						if( GC.getGameINLINE().getSorenRandNum(iBonusOdds, "Bonus Depletion") == 0)
						{
							szBuffer = gDLL->getText("TXT_KEY_MISC_RESOURCE_DEPLETED", GC.getBonusInfo(getBonusType()).getTextKeyWide(), GC.getImprovementInfo(getImprovementType()).getDescription());
							gDLL->getInterfaceIFace()->addMessage(getOwnerINLINE(), false, GC.getEVENT_MESSAGE_TIME(), szBuffer, "AS2D_FIRSTTOTECH", MESSAGE_TYPE_MINOR_EVENT, GC.getBonusInfo(getBonusType()).getButton(), (ColorTypes)GC.getInfoTypeForString("COLOR_RED"), getX_INLINE(), getY_INLINE(), true, true);
							pCity = GC.getMapINLINE().findCity(getX_INLINE(), getY_INLINE(), getOwnerINLINE(), NO_TEAM, false);
							GC.getGameINLINE().logMsg("Resource Depleted! Resource was %s", GC.getBonusInfo(getBonusType()).getTextKeyWide());
							setBonusType(NO_BONUS);
							if (pCity != NULL)
							{
								pCity->AI_setAssignWorkDirty(true);
							}
						}
					}
				}
			}
		}
/************************************************************************************************/
/* Afforess	                     END                                                            */
/************************************************************************************************/
	}

	doImprovementUpgrade();
}

 

[Afforess]

Gah. Double posts kill kittens.

 

[xienwolf]

Personally, I use a heavily modified version of Gerike's OOS Logger, and I wrote my own logger for the random numbers which will supply you with additional information (precise turn number and text string used in making the random). Between those two, figuring out what caused an OOS is far less painful. I can't imagine trying to use Firaxis's MPLog.

 

[Afforess]

Care to share how to create such a logger?

 

[EmperorFool]

Yeah, was that post meant to just tease us, xienwolf?

 

[xienwolf]

Sorry, I'll look for the link to Gerike's original thread with his basic logger. For the modified version of the RNG logging and Gerike's OOS logger, you'd have to download Fall Further and swipe it from there. I can't remember what all I added to the OOS logger, pretty sure none required new DLL to python exposures. Mostly it was just getting you co-ordinates of the cities and some basic status updates to make sense out of the other numbers (knowing that some random warrior at (51,298) lived in one logger and didn't in another doesn't help much with finding in the savegame WHERE the errant combat happened)

EDIT: Post 7 of his thread

 

[Afforess]

I have the latest FF, can I just drop the OOS logger into my python folder and expect it to work?

 

[EmperorFool]

Ah, that OOSLogger basically dumps the state of the game every turn.

 

[xienwolf]

There was a single line you have to make a change/addition for in the Event Manager. OOSLogger only dumps the state when an OOS triggers, so that is where you need to add the line, is in the onOOSTrigger or whatever it is called, you put a line to call up the logger and then it generates the data dump. It will only do one dump per game (the first instant an OOS is noticed).

Gerike's download has instructions on what the one extra line is, and HIS logger will work instantly for you. Mine MIGHT have some features which aren't available/exposed in your mod, since I have added to it. I think all my additions were pretty fundamental and not FfH specific though.

Also, not EVERY potential OOS indicator is checked each turn. As I recall, it is in the course of 4 turns that all data winds up being checked (25% of all possible indicators are checked each turn, in a cyclical order). Adjust this so that ALL sources are checked each turn means a SLIGHT performance reduction, but a more instant notice of OOS. The random seed I am pretty sure IS checked each turn though.