Debug Techniques - Floating Gardens

[carloscodex]

This one killed me for almost three weeks.

Every turn the FLOATING GARDENS would appear. I had read somewhere that this had something to do with potential errors in the construction of the Buildings table or something like that.

Well, I removed the Buildings table (and all linked objects -- too much tight coupling, yuck) and I still had the floating gardens appearing after every turn.

So, I brute forced it.

Bit by bit I removed functionality from my mod (Prehistoric). It's rather large, now, so there was a lot to remove. And there were so many dependencies (bad design) that I would have to fix it all the time.

I got to the point where the ONLY custom content I had was ONE custom technology and ONE custom era. And I still got the FLOATING GARDENS.

Here is the important part: The lua logs showed NOTHING! The database.log file and other logs showed nothing. Never. Not since the start. This is why I brute forced it.

I finally realized that I had accidentally left in a lua file reference "InGameUIAddon". In that file I had a reference to GameInfoTypes.OLD_BUILDING_NAME.

I had changed the name a while back.

So, my question to all of you: How should I have debugged this? Is there is some debug log I am missing? Some config level I am missing? I don't want to go through this again.

Thanks in advance!


P.S. My "Database.log" file sometimes does not get refreshed when I reload my game. Anyone know why this would be? I have to quit the game completely and restart.

 

[Vicevirtuoso]

Getting unintentional Floating Gardens doesn't necessarily mean that there is a problem with the entire Buildings table. (Otherwise, you very well may not even have that building in it!) Floating Gardens tends to be ID 0 in the Buildings table. When SetNumRealBuilding is passed a bad value for the buildingID, such as nil, it will default to 0 instead of return an error. Thus, any GameInfoTypes.BUILDING_XYZ which isn't defined will just be substituted with Floating Gardens. So in your logs, you're gonna want to be looking for errors loading your custom Buildings. Lua, however, will return no errors -- so you'll need to just manually look through your code for stuff like SetNumRealBuilding in your functions to find what's causing it.

Database.log is a bit iffy sometimes. If I'm debugging database info, I usually restart the game each time.

 

[carloscodex]

Thanks for the great response.

Lua, however, will return no errors -- so you'll need to just manually look through your code for stuff like SetNumRealBuilding in your functions to find what's causing it.

I found it, but it was such a pain since I didn't know about that call. So, the essence of my question is: HOW and WHERE do we capture these exceptions and see them? There could be any number and type, this being just one example.

Database.log is a bit iffy sometimes. If I'm debugging database info, I usually restart the game each time.

This is nuts. There must be a way to explicitly flush the logs. If not, this would be a great DLL/EXE hack.

--

THANKS AGAIN!

 

[DarkScythe]

One thing you can do is embed print() statements into the Lua to echo whatever your function is doing / has done with whatever value it's received. This would print a line into the logs and you can check to make sure your functions are working properly this way.

Otherwise, another thing you might be able to make use of is assert() which will halt execution if something doesn't match up with what you expect the function to find.

I tend to get a bit carried away with my debug print() statements, though...

 

[Vicevirtuoso]

I found it, but it was such a pain since I didn't know about that call. So, the essence of my question is: HOW and WHERE do we capture these exceptions and see them? There could be any number and type, this being just one example.

Well, for this example in particular, you could create a wrapper function like so:

function VV_SetNumRealBuilding(pCity, iBuilding, iNum)
	if (iBuilding ~= nil) then
		if (GameInfo.Buildings[iBuilding]) ~= nil then
			pCity:SetNumRealBuilding(iBuilding, iNum)
		else
			print("ERROR: Unable to find building ID "..iBuilding.." in the Buildings table")
		end
	else
		print("ERROR: iBuilding value is nil in VV_SetNumRealBuilding")
	end
end

To ensure everything in your mod has loaded in general, you may just want to put a function in your Lua script which checks GameInfoTypes for everything your mod adds, and prints the result of each.

 

[carloscodex]

To ensure everything in your mod has loaded in general, you may just want to put a function in your Lua script which checks GameInfoTypes for everything your mod adds, and prints the result of each.

Thanks, this will help with the non-reporting of those specific types, but what about other non-reporting non-logging issues? Where does the stacktrace go? I am concerned that I am missing important uncaught exceptions.

I have a Logger class that helps out:

Spoiler :

--[[

Logger [pseudo-class]

@desc:    Standard logging utilies using typical log levels. 
@author:  apshai(steam), carloscodex(civfanatics), carlosfhernandez(github)
@date:    2014-01-05


USAGE
--------------------------------------------------------------------------------

Create a new logger.

Use your favorite  :o)  log level: DEBUG, INFO, WARN, ERROR, FATAL:
> local logger = Logger:new(Logger.LEVEL.DEBUG)

Or, use the default log level (in Logger.DEFAULT)
> local logger = Logger:new() 


Change your mind? Update log level.

> logger.level = Logger.LEVEL.WARN


Log a message.

> logger:log( "like codex?" ) -- will use current log level, Logger.level
> logger:log( "override level", Logger.LEVEL.FATAL)
> logger:log( "custom format", nil, "%date %level %message\n")
  -- nil will use current log level

> logger:debug( "just output at debug level" )
> logger:info( "same for all others" )


SAMPLE LOG
--------------------------------------------------------------------------------

Main_Pre: 14-01-17 12:01:14  INFO PlayerDoTurn.Add( CanBuild_Causeway )


FUTURE
--------------------------------------------------------------------------------

Better inline comments. (Don't we always say that?)

Logger:convert (obj)
If supplied message is not a string then Logger will attemp to serialize or 
convert to string format. Tables, Arrays, etc, will be converted for 
wonderful debugging opportunities! :P

Logger:hook (x) --- eh, maybe

Logger.add_output (io, file, net?)
I don't even know if it's possible within the Civ sandbox, but it would be nice
to send log info to a designated URL. Of course, this would probably pose a 
security issue, so we'll see how this goes. 


ANOTHER LOGGER?
--------------------------------------------------------------------------------

Yes. This was my first day learning Lua so I decided to try something somewhat
familiar to get my hands dirty. Now I need to go read some reference books and 
manuals and get a decent foundation. 


CONTACT
--------------------------------------------------------------------------------

Please contact me for questions and suggestions. 

apshai(steam), carloscodex(civfanatics), carlosfhernandez(github),
carloscipher(twitter)


--]]




-- module "util"

print( "logger    | --------------------------------------------------" );
print( "logger    | __FILE__ util/logger" )
print( "logger    | --------------------------------------------------" );




--
-- Logger 
--
-- 
--
Logger = {
  DEBUG   = "DEBUG",
  INFO    = "INFO",
  WARN    = "WARN",
  ERROR   = "ERROR",
  FATAL   = "FATAL",
  LEVEL   = {
      DEBUG = 1,
      INFO  = 2,
      WARN  = 3,
      ERROR = 4,
      FATAL = 5
  }
}

Logger.DEFAULT        = Logger.LEVEL.ERROR
Logger.DATE_PATTERN   = "!%y-%m-%d %H:%m:%S "
Logger.PATTERN        = "%date %level %message\n"
Logger.PREFIX         = ""


--
-- new
--
-- @param 
--
-- Create new logger.
--
function Logger:new (level)
  self.level = level or self.DEFAULT
  return self
end



--
-- log
--
-- @param {String} msg
-- @param {String} level 
-- @param {String} pattern
-- @param {String} prefix - prefix to be added to message
-- @param {Boolean} bPersisPrefix - whether to keep this prefix for future msg
-- 
function Logger:log ( msg, level, pattern, prefix, bPersisPrefix )

  if (false or bPersisPrefix) then
    self.PREFIX = prefix or ""
  end

  if level then
    assert(self.LEVEL[level], string.format("undefined level `%s'", tostring(level)))
  else
    level = self.level
  end 

  if self.LEVEL[level] >= self.level then

    if type(msg) ~= "string" then
      msg = self:convert(msg)
    end

    print( self:messagize(pattern, os.date(self.DATE_PATTERN), level, msg) )

    return true

  else
    return false

  end

end

--
-- debug 
--
function Logger:debug ( msg, pattern )
  self:log ( msg, self.DEBUG, pattern, nil, false )
end

--
-- info 
--
function Logger:info ( msg, pattern )
  self:log ( msg, self.INFO, pattern, nil, false )
end

--
-- warn 
--
function Logger:warn ( msg, pattern )
  self:log ( msg, self.WARN, pattern, nil, false )
end

--
-- error 
--
function Logger:error ( msg, pattern )
  self:log ( msg, self.ERROR, pattern, nil, false )
end

--
-- fatal 
--
function Logger:fatal ( msg, pattern )
  self:log ( msg, self.FATAL, pattern, nil, false )
end

--
-- messagize
--
function Logger:messagize (p_pattern, dt, level, message)

    local logline = p_pattern or "%date %level %message\n"

    message = string.gsub(message, "%%", "%%%%")

    --logline = string.gsub(logline, "%%date", dt)
    --logline = string.gsub(logline, "%%level", level)
    --logline = string.gsub(logline, "%%message", message)


    logline = string.format("%-10s| %s%s %s", self.PREFIX, dt, level, message)
    --logline = string.format("", ) .. logline

    return logline

end

--
-- convert
--
function Logger:convert (obj)
  return "[SYSTEM] String conversion function not supported, yet..."
end

and it makes logging easier, but again, what about uncaught and/or unlogged exceptions? Does anyone know where they go? Is this something where we would need to hack an exe/dll in order to see what is going on? Do we have to explicitly set an option to log ALL exceptions (like a log level debug somewhere)?

Thanks again. I hope someone knows.

Cheers.