Debug Log File

When there is too much going on to show everything on screen, details of what is going on can be sent to a log file that can be checked later.

This can be done with a very simple function.

function DebugOut( thisString$ )
   thisFile = opentowrite( "debug.txt" , 1 )
   writeline( thisFile , thisString$ )
   closefile( thisFile )
endfunction

This opens a file called debug.txt in append mode (the 1 parameter after the name), writes a string of text to the file, then closes the file.

At the start of the program - just before the call to Initialise(), we now check for and remove any old debug log.

// *** DIAGNOSTIC LOGGING ***
if getFileExists( "debug.txt" ) then deleteFile( "debug.txt" )
DebugOut( "Calling Initialise()" )
// *** DIAGNOSTIC LOGGING *** 

This ensures that each run of the program clears the file and starts again.  It then uses the new function to log the fact that it is calling the Initialise() function.

The comment lines before and after are to draw attention to the presence of this code to make it easier to find and remove later.

The program will run as before, but now a file will be created called debug.txt which will look like this.

Calling Initialise()

AGK uses a designated write area, which varies from system to system.  On Windows this is in an AGK folder within your My Documents folder, with a sub folder for the project and it's media.

On my system, the file is in.

S:\Users\Marl\Documents\AGK\Build-It\media

With the file being created ok, we can now set about locating the problem by putting diagnostic logging calls at key places in the LoadObjectData() function.

At the very start, we add lines which indicate the start of the Load function and the parameter passed in quotes.

function LoadObjectData( thisName$ )
   // Pass the name without extension

// *** DIAGNOSTIC LOGGING ***
DebugOut( "LoadObjectData() called with " + chr(34) + thisName$ + chr(34) )
// *** DIAGNOSTIC LOGGING ***

After the closefile() command, we indicate how many lines were read.

// *** DIAGNOSTIC LOGGING ***
DebugOut( "Lines read : " + str( thisArraySize ) )
// *** DIAGNOSTIC LOGGING ***

At the end of the for i=1 to topObject() loop, just before the last endif, we output the object details stored in the array.

// *** DIAGNOSTIC LOGGING ***
DebugOut( "Object : "+str(i)+" = "+chr(34)+ObjectName(i)+chr(34)+", Icon: "+str(ObjectIcon(i))+", Detail: "+chr(34)+ObjectDetail(i)+chr(34)) 
// *** DIAGNOSTIC LOGGING ***

         endif
      next i
      // Recipes Go Here

This shows the initial values set for the name, icon and detail strings of each object.

At the start of the group membership section, we log the fact.

      // Group Memberships

// *** DIAGNOSTIC LOGGING ***
DebugOut( "Group Memberships") 
// *** DIAGNOSTIC LOGGING ***

And within the group loop, we log if a group is found with members.

      for i=1 to topObject()
         if ObjectIsGroup( i ) > 0 and ObjectDetail( i ) <> ""

// *** DIAGNOSTIC LOGGING ***
DebugOut("Group "+str(i)+" has members "+chr(34)+ObjectDetail( i )+chr(34))
// *** DIAGNOSTIC LOGGING ***

            game.groupObject$ = game.groupObject$ + Base96Encode( i )

Following the FindObjectByName() call, we log the used name and resulting object reference.

               thisObject$ = mid( thisString$ , thisStart , thisComma - thisStart )
               // convert to base96
               thisObject = FindObjectByName( thisObject$ )

// *** DIAGNOSTIC LOGGING ***
DebugOut("..Name "+chr(34)+thisObject$+chr(34)+" is object "+str( thisObject ))
// *** DIAGNOSTIC LOGGING ***

               if thisObject > 0 then thisCoded$ = thisCoded$ + Base96Encode( thisObject )

This covers the main stages of the conversion of the group memberships and should give a better idea of the problem.

When we run the program, and then check debug.txt, we see this.

Calling Initialise()
LoadObjectData() called with "standard"
Lines read : 14
Object : 1 = "tool", Icon: 1, Detail: "stone axe"
Object : 2 = "resource", Icon: 2, Detail: "tree,stone"
Object : 3 = "device", Icon: 3, Detail: ""
Object : 4 = "job", Icon: 4, Detail: ""
Object : 5 = "process", Icon: 5, Detail: ""
Object : 6 = "storage", Icon: 6, Detail: ""
Object : 7 = "tree", Icon: 7, Detail: "Home to Birds and Monkeys"
Object : 8 = "stone", Icon: 8, Detail: "Small hard piece of planet"
Object : 9 = "stone axe", Icon: 9, Detail: "Primative chopping device"
Object : 10 = "log", Icon: 10, Detail: "Rough tree part, might burn well"
Object : 11 = "kindling", Icon: 11, Detail: "Basis of a good fire"
Object : 12 = "spark", Icon: 12, Detail: "Warning - fire Hazard"
Object : 13 = "flame", Icon: 13, Detail: "Fire's younger sibling"
Object : 14 = "fire", Icon: 14, Detail: "Good source of heat and light"
Group Memberships
Group 1 has members "stone axe"
..Name "stone axe" is object 0
Group 2 has members "tree,stone"
..Name "tree" is object 0
..Name "stone" is object 0

Which shows the problem is that all object names are returning object value zero. The problem is in the FindObjectByName() function.

Within that function, we log the fact that the function has been called, the parameter passed and the result.

function FindObjectByName( thisName$ )
   thisName$ = upper( thisName$ )
   for thisObject = 1 to TopObject()
      if upper( ObjectName( thisObject )) = thisName$ then exit
   next thisObject

// *** DIAGNOSTIC LOGGING ***
DebugOut("FindObjectByName() Called with "+chr( 34 )+thisName$+chr(34)+", Result: "+str(thisObject))
// *** DIAGNOSTIC LOGGING ***

   if thisObject > TopObject() then thisObject = 0
endfunction thisObject

Which now changes the bottom part of the log file to

Group Memberships
Group 1 has members "stone axe"
FindObjectByName() Called with "stone axe", Result: 15
..Name "stone axe" is object 0
Group 2 has members "tree,stone"
FindObjectByName() Called with "tree", Result: 15
..Name "tree" is object 0
FindObjectByName() Called with "stone", Result: 15
..Name "stone" is object 0

What is interesting here is that the logged output shows the parameter passed in each case as lower case, yet the first call of the function changes this to upper case using the Upper() command.

Testing the Upper() command with some test code such as

testString$ = "Hello World"
print( chr(34) + upper( testString$ ) + chr(34) )

which returns "", shows that it is this command which is the problem.

This was logged as issue 282 on the AGK reporting board ( code.google.com ).

The workaround for this - to get the project running - is to change the strings to lower case, rather than upper case.  The effect is the same, we simply want the case to be the same in the comparison.
This involves changing all references to upper() to lower().

function FindObjectByName( thisName$ )
   thisName$ = lower( thisName$ )
   for thisObject = 1 to TopObject()
      if lower( ObjectName( thisObject )) = thisName$ then exit
   next thisObject

With this change, the app is back to its working state.

Now the detail fields for objects 1 and 2 are populated correctly and the stone axe is once again displayed.

The debug.txt file also shows everything as it should be.

Calling Initialise()
LoadObjectData() called with "standard"
Lines read : 14
Object : 1 = "tool", Icon: 1, Detail: "stone axe"
Object : 2 = "resource", Icon: 2, Detail: "tree,stone"
Object : 3 = "device", Icon: 3, Detail: ""
Object : 4 = "job", Icon: 4, Detail: ""
Object : 5 = "process", Icon: 5, Detail: ""
Object : 6 = "storage", Icon: 6, Detail: ""
Object : 7 = "tree", Icon: 7, Detail: "Home to Birds and Monkeys"
Object : 8 = "stone", Icon: 8, Detail: "Small hard piece of planet"
Object : 9 = "stone axe", Icon: 9, Detail: "Primative chopping device"
Object : 10 = "log", Icon: 10, Detail: "Rough tree part, might burn well"
Object : 11 = "kindling", Icon: 11, Detail: "Basis of a good fire"
Object : 12 = "spark", Icon: 12, Detail: "Warning - fire Hazard"
Object : 13 = "flame", Icon: 13, Detail: "Fire's younger sibling"
Object : 14 = "fire", Icon: 14, Detail: "Good source of heat and light"
Group Memberships
Group 1 has members "stone axe"
FindObjectByName() Called with "stone axe", Result: 9
..Name "stone axe" is object 9
Group 2 has members "tree,stone"
FindObjectByName() Called with "tree", Result: 7
..Name "tree" is object 7
FindObjectByName() Called with "stone", Result: 8
..Name "stone" is object 8

With that confirmed as working, we can now go through and remove all the diagnostic logging code and the block added to print the details in the main loop.

Though I'm sure we'll be seeing it again soon so the DebugOut() function can stay.

Tracking down this issue was made so much easier by the fact the program is modular, and this also meant that the change to rectify it was limited to just one place.