goblinsInUrWorkshop

Desktop Tuesday: Debugging 101

Hey everyone, Stephanie here. The whole team is heads down fixing A12 bugs this week, so I thought I’d do a fast Desktop Tuesday about debugging basics, and how your bug reports actively help us make the game better.

What is a Bug?

Like all games, Stonehearth can be boiled down to the following:

  • a giant heap of code, distributed among hundreds of text files
  • an even bigger pile of art/music assets

Code (whether C++, Lua, Javascript, or HTML) is a series of words and numbers that tell the computer how the objects in the game should behave. You can think of it as a specialized set of instructions that the computer understands. All the objects in the instructions (nouns) are stored in “variables” and all the verbs are represented by logical statements (if/else, while, for, etc).

When you have thousands of lines of instructions, it’s easy for two of them to accidentally contradict each other, or produce a behavior that is unexpected. When that happens, it’s a bug. (Named so, because once upon a time, an unexpected behavior was caused by an actual moth, trapped in a giant computer.)

Noticing a Bug

The Stonehearth team has a few means of noticing bugs:

Microworld:

carpentermicroworld

As we build features, we run them in specialized test worlds like the ones in our microworld repository. Microworlds contain ONLY what is required to make a feature work. If for example, I am working on crafting, I make a microworld that contains only one kind of crafter and the ingredients required for her recipes. I test here until the crafter makes the items as expected. This way, if there is unexpected behavior in my code, I know that it has to do ONLY with my code, and not with any complicating factors.

Autotests:

Whenever we’re done with a feature, we try to write an autotest for it. An autotest is a microworld, like the one used for development, but with code that pretends to be the user, and clicks buttons to exercise the behavior. This way the behavior can be tested without any actual user input. Whenever we check code into our central repository, we run all the autotests everyone has ever written.Ā If any of the autotests fail, we know our code broke something in some other feature, and we must fix that before we can put the code into the official version of the game.

Playing the Game:

And of course, we play the game! If we find bugs during this process, we note them in our bug database, and try to figure out which part of the game caused the bug, and who is the best person to fix it. The bug is assigned to that person. If an engineer tries to fix a bug in an area of the code they are not familiar with, it can take a long time, and they run the risk of breaking other things. We try to be efficient about who fixes what.

Your Bug Reports:

yourBugReports

We are only eight people, and we can only play the game for so long before we notice something wrong, fix it, invalidate our existing save, and then have to start over. šŸ˜‰ This is why your bug reports are so important to us. There are a lot more of you than there are of us, you notice a lot more than we can, and you play the game longer than we tend to be able to.Ā Things we deeply value about your bug reports:

  • Clear reproduction steps. If you can tell us exactly how to get the bug to happen every single time, we can go straight to fixing it, as opposed to trying to get it to happen, and then failing, repeatedly. You save us mountains of time when you give us good repro steps.
  • Saved game in which the bug happens, every single time. This is just as good as clear reproduction steps, especially for big games with complex interactions, where it’s not clear exactly how to get the problems to happen.
  • Your Stonehearth Logs. Stonehearth.log is a file that is generated every time you play the game. It lives in the folder right beside stonehearth.exe. When we write code, sometimes we remember to have the code leave a line in the log whenever something interesting happens.

Many thanks to David P, this is one of theĀ most beautiful things I saw yesterday:

beautiful

Fixing a Bug

Debuggers

Once we know how to reproduce a bug, we still need to find out which line (or lines!) of code is causing the problem. One solution is to use a debugger. Remember how I said above that code is a series of instructions that the computer uses to figure out what should happen in the game? Most of the time, these instructions are read linearly by the computer. Instruction A follows instruction B, etc. Debuggers (Visual Studio for C++, Decoda for lua, Chromium Embedded for HTML/javascript) allow you to look at your code while it is running, pause the game in a certain instruction, and examine the state of the variables (nouns) involved in that code at that time.

In the example below, you can see that the inventory thinks that there are 2 sacks of flour in the world, but according to the screen, you can actually see three. That means that we need to look more closely at the inventory, and how it adds/removes objects from its awareness.

trackingDataOff

Logging

If you have NO idea where in your code a problem is happening, one solution is to write all your behavior to a log, and then read the log afterwards to figure out what is happening. This is actually what I recently did with the crafters-getting-stuckĀ bug from last week. Since the problem never happened while I was running the game with the debugger on, and since saving/loading fixed the problem, I could not look at a faulty instance and use the debugger to track where the code was misbehaving. Instead, I added logging to the crafting workflow, and printed the crafter’s current behavior to the log every time he did something.

This is how you declare that you want to use logging in a file:

createLogger

Note that you need to give the log a namespace. In this case, it’s “crafter.”

And this is how you use the logger that you’ve created:

usingLogs

Note that when you write a log, you give it a level of detail. We have 6 default ones:

ERROR = 1
WARNING = 3
INFO = 5
DEBUG = 7
DETAIL = 8
SPAM = 9

Writing to the log slows the game down, so it’s important that only the logs that you want are written out to the log file. To do this, we turn off all logging by default.Ā Then, we turn on logs by namespace in our user_settings.json file. This, for example, is what mine looks like:

user_settings

You can see that the crafter log is active, and it is at the “detail” level, so all logs that are “detail” or lower will be included. This way you can set the granularity of your logging.

As you can see from the entries that are peers to crafter, I’ve asked for other kinds of logs in the past (pace_keeper, ai, combat, etc) but right now, they are all turned off; the underscores prevent them from matching the namespaces in the code. But I can turn them back on again really quickly, if I need them.

Many thanks to everyone who turned on crafting logs last week and sent them to me. I looked at ALL of them, and I think I’m pretty sure where the problem is.

shfanlog

In this log from StonehearthFan, we can see that carpenter Campton Rayne looks for a new order, tries to drop his crafter pack items… and then never does anything carpenter related again. What happened? Probably, the drop action failed, but we did not exit properly from the loop. Ouch!

shouldexit

Hopefully it will be fixed in the next unstable release. In the meantime, if you want to speed your game up a bit, you can turn the logs back off by removing the logging section, or by just adding an underscore in frontĀ of the “crafter” tag.

And that’s it for this week! Keep those bugs coming, and stay tuned for another unstable release soon. šŸ™‚