Debugging: The Log

Right now a lot of my time is spent fixing bugs in the code. Given that the game is large and complex, it can be hard to know just what happened that led up to a bug. So we keep track of everything important.

This is actually something that we did in King of Dragon Pass. Shawn Steele was implementing our scripting language, OSL, and wanted a way to check that things like conditionals and calculations worked. So he came up with a way to log this to a file. You can see his focus from some of the options:

kAllBranches = 0x01,
 kListSizeing = 0x02,
 kTraceOSL = 0x04,
 kTraceMath = 0x08, // Extra COSL::StartMath debugging information
 kSetVariables = 0x10,
 kTraceFixed = 0x20, // Extra CFixed debugging information
 kLoadVariables = 0x40,
 kGetStrings = 0x80,
 kTraceTribes = 0x100,
 kTraceOSLVariables = 0x200, // CFixed::PrintFileDebug should print OSL Variable Names the hard way
 kTraceMathResult = 0x400,
 kTraceList = 0x800, // Attempt to show list content

The output shows addresses and opcodes, showing its focus on debugging the language:

OSL 0xd8b694 Running from 0, fRunDepth 0:
-------------------------------------------
0000 : 0202 019E Picture "scene018" 
0002 : 0203 0001 Position 0001 
0005 : 4005 E
 Loading Variable 4005 (E) 0.000 (gValue)
0006 : 0800 = 
0007 : 068D RandomElement 
0008 : 0480 ( 
0009 : 070E ClanMembers 
000A : 0841 - (subtract) 
000B : 0718 RingMembers 7ffa0000 -- P00000000:0021a700 (gValue)
 Result: 7ffa0000 -- P00000000:005e18fe (gValue)
000C : 0481 ) -- gValue = 7ffa0000 -- P00000000:005e18fe (gValue)7ff20001.0000 : Brenna (gValue)
 Setting Variable 4005 (E)
 Result: 7ff20001.0002 : Brenna (gValue)
000E : 4021 otherClan
 Loading Variable 4021 (otherClan)7ff30017.0000 : Blue Jay (gValue)
000F : 0800 = 
0010 : 068D RandomElement 
0011 : 0480 ( 
0012 : 068A NeighboringClans 
 4 COSL::Neighbors:
Clans:
 9 Boskovi
 15 Blackrock
 18 Greydog
 23 Blue Jay

0013 : 0481 ) -- gValue = 7ffb0000 -- C00000000:00848200 (gValue)7ff30012.0000 : Greydog (gValue)
 Setting Variable 4021 (otherClan)
 Result: 7ff30012.0000 : Greydog (gValue)
0015 : 4012 R
 Loading Variable 4012 (R) 0.000 (gValue)
0016 : 0800 = 
0017 : 0600 FALSE 0.000 (gValue)
 Setting Variable 4012 (R)
 Result: 0.000 (gValue)
0018 : 0212 01A4 Saga "<4005> told us we should take in Orlkensor Bronzebones, a warrior outlawed by the <21>.plural." 
 Loading Variable 4005 (E)7ff20001.0002 : Brenna (gValue)
ReplacePlaceHolders...7ff20001.0002 : Brenna (gValue)
 Loading Variable c321 (otherClan)00000000.0000 : Greydogs (gValue)
ReplacePlaceHolders...00000000.0000 : Greydogs (gValue)
001A : 0201 01CF Music "IsItAdventure" 
001C : 0A00 NewChoices

Once OSL was reliable, it turned out that the log was useful to help debug the OSL scripts themselves. If something weird happened, you could see what code branch was taken, and what some of the variables were. For example, the output above shows all the neighboring clans

And we output other information to the log, such as the scene queue, some of the clan decisions, and more.

The debug log can grow quite large (a quick search shows one at 7.7 MB), so the game makes a new one every time you launch. But if you had to relaunch because of a crash, that would mean that any evidence would be deleted. So actually, we rename the log, and actually delete the previous one.

While I reworked OSL for Six Ages, I based it on Shawn’s work, and wasn’t so concerned about debugging the language itself. Instead, I wanted to focus on the scripts, since that seemed like where most of the bugs would be.

<OSL: 0x170194ec0> ® 2 Affiance her to …
-----------------
: Saga "We affianced her to <.an> <ourClan> groom." {a} {C_1 Arrowstone}
: (ourClan).commoners {277}
: += 
: # 1 {277} {278}
 ourClan.commoners ← 278
: ChooseYesNo
: ( 
: String "Do you accept the 10 cows?" 
: ) ↖︎ = Do you accept the 10 cows?
sendToCurrentScene: kNewChoice
… exploded
Restarting OSL (self.result=kNewChoice)

This is more compact (thus easier to read): more values are shown on the same line, and it doesn’t bother to show addresses or opcodes.

The next post will talk more about how to make use of this.

Author: David

Creator of Six Ages and King of Dragon Pass View all posts by David