Structured Logging in GML

Last updated on Dec 20, 2023

Ah, show_debug_message(), how can we live without you? It’s bread-and-butter for debugging.

However, it’s a mess. If you add that everywhere without cleaning it up, your console output is going to look like word salad as a stream of random numbers and strings like “here” or “aaaaa” or “asdfsdfsdf” you threw in there at random points during debugging comes out. Then, as soon as you tidying up and delete all the debug messages, thinking you're done with them, suddenly another bug happens that need you to put those back.

Fortunately, there’s more you can do with logging than just show_debug_message(), including different log severity levels, structured logging, the whole caboodle. I’ll try and cover a few of the ideas behind better logging that can help you organize your logs better. Particularly important if you start using GameMaker as a server, or to automatically collect crash reports.

The link below is the logging constructor I use for my own projects that encapsulate some of the ideas here.

Debug messages as a permanent feature of code

I believe that a lot of debug messages should be a permanent feature of the code. Not just added when things go wrong, and commented out later. You might need your logs not just in the moment of debugging, but maybe later on, if only to confirm that some old code that broke in the past didn't break again. So why not make the debug messages a permanent feature of the code? Instead of treating show_debug_message() as something you throw in temporarily to be removed later, enshrine it as a permanent part of your code, and give it the functionality needed to allow you to easily manage it and make it useful without drowning you in random debug messages all the time.

The simplest example is: use a macro to enable/disable logging. This way, using GameMaker's configuration selector, you can globally turn on and off all log messages

#macro LOG_ENABLED false
#macro testing:LOG_ENABLED true

function log(_message) {
  if (LOG_ENABLED) show_debug_message(_message);
}

This is very rudimentary, of course, but this is just the start, and it’s the foundational concept: debug Messages are logs about how your program runs, and a permanent part of your code (as permanent as any other code anyway).

Named Logging instances

Ok, so we have permanent logging in our code, this is great if we needed all those logs, but it’s still a mess if we have a lot of it. So we need to be able to individually control different sets of logs so that we can disable what we don’t want to see, and enable what we do want to see. That way, if you’re debugging the player’s state machine, you can turn those logs on, and turn off all the other logs that aren’t relevant.

To do this, we need to treat groups of logs together, rather than have singular calls to a generic log() function. We can make use of constructors to create logging instances:

function Logger(_name="Logger", _enabled=true) constructor {
  self.enabled = _enabled;
  self.name = _name;

  static log = function(_message) {
    if (self.enabled) show_debug_message($"{self.name}: {_message}");
  }

  static set_enabled = function(_enabled) {
    self.enabled = _enabled;
    return self;
  }
}

With this, we can create individual logger instances for different objects or systems, each with their own set_enabled() functions. We also have the start of some custom log formatting (in this case, the string name is added to the front of every log message so that you can see which logger produced the message).

The use case would be: let’s say you have a player object which has its own distinct set of logs it needs to produce, like state transitions, or player state, or item pickups, or whatever. We can create an instance variable containing our logging instance that can be separately configured to any other logging instance in the game.

logger = new Logger("Player");
logger.log("hello")

// output:
// Player: hello

If you want to silence your player logs, simply turn it off by changing the default enable value it starts with

logger = new Logger("player", false);
logger.log("hello")

// no output!

If you create a more elaborate system, you could also toggle the enable state in code. Perhaps you have a debug overlay that has buttons to turn on and off different loggers, you can use the .set_enabled() method to do so.

Log Severity Levels

Not all log messages are created equal. Your average “aaaa” log message isn’t as important as a message that tells you about the change in some state you want to care about, and both aren’t as important as a log message that tells you something abnormal has occurred that you probably want to look into.

So, logs should have severity levels to help you pick out the important messages. And logs should be able to be silenced based on their severity. For example, in the above section, we had a logging instance that’s specific to the player object, which you could enable or disable to turn on and off all logging for that object. But what if you wanted to disable the spammy debug logs that you don’t need at this moment, but still want the more important logs? You need log severity levels.

It’s common throughout programming languages to have at least four different log severity levels:

Debug. These logs are to help debug a particular feature, and could be quite spammy. For example log messages describing how a particular algorithm is playing out. Typically you’d only ever want to see these if you’re actively debugging a particular functionality it is relevant for, and turned off the rest of the time.
Info. This is your generic log level, giving you info about the normal running of code.
Warning. This is for abnormal conditions that you, the dev, should be aware of. You’d use it for potential issues that may need corrective action, but isn’t code-breaking at the moment. For example, a controller object not existing but the game was able to spawn the object to avoid issues.
Error. This is for abnormal conditions that prevent the normal/expected operating of code. It doesn’t necessarily mean the game crashes, but rather it cannot do a thing it was intending to do. For example, loading a save file that was corrupted. In this case the result is the file cannot be loaded, so the game could not do the thing that it was being asked to do.

In some languages and logging systems, sometimes you’ll see a Trace level which is even debuggier than Debug, you’d use this even for debugging the values in a loop. Sometimes you’ll see a Fatal and even Critical level at the other end, which is like Error, but probably results in the program crashing immediately afterwards.

So we could improve our logging instance with support for the different log levels. (By the way don't copy this, the code linked at the start of this article has this in its completed form, this is just an intermediate stage to illustrate the progression from a simple to a more complete logging system).

function Logger(_name="Logger", _log_level=undefined) constructor {
  self.name = _name;
  self.__enable_error = false;
  self.__enable_warning = false;
  self.__enable_info = false;
  self.__enable_debug = false;
  self.set_level(_log_level);
  
  static debug = function(_message) {
    if (self.__enable_debug) self.__log(Logger.DEBUG, _message);
  }
  
  static info = function(_message) {
    if (self.__enable_info) self.__log(Logger.INFO, _message);
  }
  
  static warning = function(_message) {
    if (self.__enable_warning) self.__log(Logger.WARNING, _message);
  }
  
  static error = function(_message) {
    if (self.__enable_error) self.__log(Logger.ERROR, _message);
  }
  
  static __log = function(_level, _message) {
	  show_debug_message($"[{_level}] {self.name}: {_message}");
  }

  static set_level = function(_minimum_log_level) {
	  self.__enable_error = false;
	  self.__enable_warning = false;
	  self.__enable_info = false;
	  self.__enable_debug = false;
	  switch(_minimum_log_level) {
		default:
	    case Logger.DEBUG: __enable_debug = true;
	    case Logger.INFO: __enable_info = true;
	    case Logger.WARNING: __enable_warning = true;
	    case Logger.ERROR: __enable_error = true;
	  }

    return self;
  }
  
  static DEBUG = "debug";
  static INFO = "info";
  static WARNING = "warning";
  static ERROR = "error";
  static FATAL = "fatal";
}

Here, we include several statics to help indicate log level, but we also provide separate logging methods like debug() or info(). This is because the severity is intrinsic to the log message. There isn’t a situation where sometimes you want a “Set n=5” debug message needs to be a warning level, and so there’s no need to parameterize the level. The usage is now:

logger = new Logger("Player");
logger.debug("hello")
logger.warning("world")

// output:
// [debug] Player: hello
// [warning] Player: world

logger.set_level(Logger.WARNING);
logger.debug("hello")
logger.warning("world")

// output:
// [warning] Player: world

Now, our logger instance can be adjusted for severity, so we can leave most loggers set to the Info or Warning level, while the loggers relating to the thing we're actively working on set to the Debug level.

Structured Logging

While logs are mainly for humans to eventually read, that doesn't mean we can't benefit from standardizing the structure of our log messages. While the message show_debug_message($"a thing happened, my ID is ${id} and my state changed to {state}") is human-readable, it's not always easy to search for if you don't remember the words that were used.

Another benefit of standardizing the log structure is that it makes them machine-readable. Perhaps you want to automatically fire off bug reports so that the player doesn't have to copy/paste error messages into your support forums (something I'll talk about in the future in another post), or perhaps you're running GameMaker on the server and have a way to centralize these logs, and filter them by severity or keyword.

One way to standardize logging is by treating it as structured data. For this reason some people call it "json logging". Instead of just logging the tsring "Player object with ID id changed state from xyz to abc", we would log something more like "State change", {player_id: id, start_state, end_state}.

The code to do this is now too big for me to reproduce in the blog post, but take a look at the full logger that I use in some of my projects that include this feature (this is the same link as the start of the article):

Here's a comparison of what structured logging looks like versus regular-old logs:

// Without structured logging:
logger.info($"Player object {id} state change from {start_state} to {end_state}");

// With structured logging:
logger.info("State change", {player_object_id: id, start_state, end_state});

When we do structured logging, we have a much shorter message to describe what it is that we're logging, in this case a "State change", and we accompany that with all the data relevant to it, in this case the player object ID and the start and end state.

It takes some getting used to writing logs like this, but the result is often cleaner, better structured, and plugs into logging and log-related tools better. For example, if you deploy GameMaker to certain servers that have a centralized logging facility, where all the backend logs are centralized for you to search, using structured logging means you can easily query and visualize the log messages, so they look like this:

Instead of this:

Bound values

Structure logging allows us to include arbitrary pieces of data into each log message, however, it’s often the case that you always want certain data to be present in all log messages made by a particular logging instance. For example, you might want a player object's logging instance to always include the instance ID, to avoid having to manually include the data in every log output. We want to be able to “bind” these values to the logging instance.

To do this, the Logger constructor could be updated to include these extra values at the moment of creation, and store them internally so that they can be included in each log output. This is why we wanted to have logger instances; each logger instance can hold onto values like this.

See the my logging code for what this looks like (again, this is the same link as the start of the article).

The usage looks like:

global.logger = new Logger(); // the root logger

// Somewhere in a player object
logger = global.logger.bind_named("Player", {player_id: id});
logger.info("hello")

The child logger inherits all of the bound variables of its parent. You might even want to create short-lived child loggers just so that you can bind some extra variables to it.

Considerations

The more elaborate our logging process, the more likely it is that someone brings up the "b...but performance" question. Yes, structured logging and more elaborate logging systems do have a performance implication, and it is going to be something you will want to balance in terms of performance versus utility. My opinion is that most of the time logging isn’t a huge hit, and if you do have a thousand objects all streaming out logs at once, you will have an issue, and sometimes you will want to keep the Debug scope logs at a minimum.

But, the great benefit of this type of logging is you can easily find that in your code, and remove and refactor as necessary. As with all things, a good clean abstraction is one that is just as easy to add as it is to remove. And so implementing logging like this gives you options: you can easily remove and refactor it as you see fit when you start having to consider performance.

Throughout this article, I’ve talked about the different shades of logging you can do, ranging from the bare-bones "global logging function that can be turned on and off", to the much more involved "instanced structured logger, that can have values bound to it" whose power only becomes apparent once you start plugging in different ways to consume those logs. Like automated bug reporting!