Gamesmithing: Logging

Photo credit: Aapo Haapanen from Tampere, Finland [CC BY-SA 2.0 (https://creativecommons.org/licenses/by-sa/2.0)]

Lazy pun credit: myself

Logs are an essential software development tool, and this is no less true for game development. With logs, you can untangle the twisted knot you weaved in code. When bugs inevitably happen, you can use logs to find the circumstances and the context that led to the code breaking bad. Since newly-discovered bugs are by definition unexpected, a robust logging system gives you information on why they occurred. If you are using a random number generator (you probably are), you know what RNG seed led to the bug. (PROTIP: log your RNG seeds.)

While Unity has logging built in, it can be... verbose. It logs a lot of things that you don't necessarily care about. I always use my own logging system, which we'll dive into in this article. At the end of the article, I'll post my code with an MIT license. Apart from a specific section of the code (which I will highlight), the code will work just fine outside of Unity. The code is in C#.

public interface ILog
{
    void Error(Exception ex, string error, params object[] args);
    void Error(string stack, string error, params object[] args);
    void Warn(string warning, params object[] args);
    void Write(string message, params object[] args);
}

This first class defines our interface ILog. Nothing crazy here, except to note that the final parameter of each function is a params argument. That means that we can pass in an arbitrary number of arguments and they will be accessible by our object[] array 'args'. In practice, we'll only be passing in strings, but you could use the broader object class on a different implementation.

static class Log
{
    static readonly string _logName = "CollisionBendLog";
    static readonly int MAX_LOGS = 10;
    static TextWriter _logger;
}

This is the start of our static class. Since it's a static class, it can be accessed from any code file and does not need to be instantiated. _logName will be the name of the directory to store the logs in. The TextWriter _logger deals with the nitty gritty of writing strings to files. MAX_LOGS is the number of log files we store before overwriting them. Why only 10? It's not hard to store more, but it would take some (not that much) work to change the 'log incrementing' algorithm. I don't think I've ever used more than three or four logs. If I run into a problem, I look over the most recent log. If the problem seems especially hard and I want to save that log, I just copy it elsewhere. So while it’s not too much work, it’s not something that would give me any benefit.    

public static void Open()
{
    if (_logger != null) return;

    var path = Path.Combine(Directory.GetCurrentDirectory(), _logName);
    if (!Directory.Exists(path))
    
        
    

    var files = Directory.GetFiles(path).ToList();
    for (int fileIndex = files.Count() - 1; fileIndex >= 0; fileIndex--)
    {
        var file = files[fileIndex];
        var shortName = Path.GetFileName(file);
        if (shortName.StartsWith(_logName))
        {
            // Increment the log number, or delete it if it's too old.
            int logNumber;
            if (!Int32.TryParse(shortName.Substring(_logName.Length, shortName.IndexOf('.') - _logName.Length), out logNumber))
            
                
            

            logNumber++;
            if (logNumber < MAX_LOGS)
            {
                string newFile = Path.Combine(path, String.Format("", _logName, logNumber, ".log"));
                File.Move(file, newFile);
            }
            else
            
                
            
        }
    }
    _logger = File.CreateText(Path.Combine(path, _logName + "0" + ".log"));
    ((StreamWriter)_logger).AutoFlush = true;
}

Here we find the file location of our logs, or we create it if necessary. Then we process the list in reverse order, starting with the oldest logs first. We make sure it's in our expected format (starts with our _logName substring and ends with an int number), then we increment the number at the end of the file. For instance, "LogName8.txt" becomes "LogName9.txt". We'll delete the file only if we have too many logs already, as defined by MAX_LOGS. After we've handled all previous existing logs, we'll create a new one, "LogName0.txt".

internal static void Error(Exception ex, string error, params object[] args)
{
    _logger.WriteLine("*******************************************************");
    _logger.WriteLine(String.Format(error, args));
    _logger.WriteLine(ex);
}

internal static void Error(string stack, string error, params object[] args)
{
    _logger.WriteLine("*******************************************************");
    _logger.WriteLine(String.Format(error, args));
    _logger.WriteLine(stack);
}

internal static void Warn(string warning, params object[] args)
{
    _logger.WriteLine("- - - - - - - - - - - - - - - - - - - - - - - - - - - - ");
    _logger.WriteLine(String.Format(warning, args));
}

internal static void Write(string message, params object[] args)
{
    _logger.WriteLine(String.Format(message, args));
}

Next up we have our actual logging functions. All static, all simple wrappers for the TextWriter _logger's WriteLine(). As you can see, all the params object[] arrays are fed into String.Format().

internal static ILog GetLogger(Type type)
{
    return new ClassLogger(type);
}

Here's the function that will be called inside of each class. It'll let us know which class is calling the logging function, although we'll see how in this next section.

public class ClassLogger : ILog
{
    private string _loggingClass;

    public ClassLogger(Type type)
    {
        string prefix = "Assets.Scripts.";
        var typeString = type.ToString().StartsWith(prefix) ? type.ToString().Substring(prefix.Length) : type.ToString();
        _loggingClass = "[" + typeString + "]: ";
        Log.Open();
    }

    public void Error(Exception ex, string error, params object[] args)
    {
        Log.Error(ex, _loggingClass + error, args);
    }

    public void Error(string stack, string error, params object[] args)
    {
        Log.Error(stack, _loggingClass + error, args);
    }

    public void Warn(string warning, params object[] args)
    {
        Log.Warn(_loggingClass + warning, args);
    }

    public void Write(string message, params object[] args)
    {
        Log.Write(_loggingClass + message, args);
    }
}

This class isn't static, so we'll create an instance of this in each class we want to log from. We pass in the Type name of the class, which we'll use as a string to specify which instanced logger (and thus which class) is calling the log. However, each instanced logger will feed into the same log file, giving us a nice (and easy-to-parse) log. The string _loggingClass will prepend all error / log strings with the class that sent the log message.

There's one more Unity-specific hook to take a look at. This is in the class Log and requires a 'using UnityEngine;' statement.

internal static Application.LogCallback GetLogCallback(ILog log)
{
    return (logString, stack, type) =>
    {
        if (type == LogType.Exception)
        {
            log.Error(stack, logString);
        }
    };
}

This will catch any otherwise unhandled exceptions thrown by your game.

Inside any class that you want to log from, include this statement at the beginning.

public class SpanningTree
{
    static readonly ILog _log = Log.GetLogger(typeof(SpanningTree));
}

This creates an instance of a ClassLogger (that implements ILog). From inside the class functions, we can call our logger like so:

_log.Write("Graph connections, w/ new connections and no bridges");
_log.Write("Adding edge between  and  to connect components", closeTreeNode.Node.name, node.name);

Here's a snippet of a log file to give you an idea of what it looks like.

[Screens.ScreenManager]: Removing screen Topic Change Screen
[Screens.ScreenManager]: Screens: [Place Screen: Hidden], [Conversation Screen: Active]
[Screens.Conversation.Player.ConversationPlayerController]: Now on node 16 at 32,3
[Screens.Conversation.Player.ConversationPlayerController]: Now on node 17 at 34,5
[Screens.Conversation.ConversationScreen]: Adding EndLevelScreen
[Screens.ScreenManager]: Adding screen Conversation End Screen

Here's the code - as stated before, it can be reused under an MIT license.

using System;
using System.IO;
using System.Linq;
using UnityEngine;

namespace Assets.Scripts.Logging
{
    public interface ILog
    {
        void Error(Exception ex, string error, params object[] args);
        void Error(string stack, string error, params object[] args);
        void Warn(string warning, params object[] args);
        void Write(string message, params object[] args);
    }

    /// <summary>
    /// Static class to log errors, warnings, and information.
    /// </summary>
    static class Log
    {
        static readonly string _logName = "CollisionBendLog";
        // There's a bug related to file enumeration that prevents this from having more than 9 log files.
        // Specifically, this looks at log9 before it looks at log10 and crashes when it tries to move log9.
        // Fixable, but won't unless the limited number becomes an issue.
        static readonly int MAX_LOGS = 10;
        static TextWriter _logger;

        /// <summary>
        /// Creates a new logging file, increments any older files so that we're always keeping a certain number.
        /// The TextWriter passed back by Open needs to surround any code that calls this class.
        ///
        /// This function changes log4 to log5, log3 to log4, etc.
        /// </summary>
        public static void Open()
        {
            if (_logger != null) return;

            var path = Path.Combine(Directory.GetCurrentDirectory(), _logName);
            if (!Directory.Exists(path))
            
                
            

            var files = Directory.GetFiles(path).ToList();
            for (int fileIndex = files.Count() - 1; fileIndex >= 0; fileIndex--)
            {
                var file = files[fileIndex];
                var shortName = Path.GetFileName(file);
                if (shortName.StartsWith(_logName))
                {
                    // Increment the log number, or delete it if it's too old.
                    int logNumber;
                    if (!Int32.TryParse(shortName.Substring(_logName.Length, shortName.IndexOf('.') - _logName.Length), out logNumber))
                    
                        
                    

                    logNumber++;
                    if (logNumber < MAX_LOGS)
                    {
                        string newFile = Path.Combine(path, String.Format("", _logName, logNumber, ".log"));
                        File.Move(file, newFile);
                    }
                    else
                    
                        
                    
                }
            }
            _logger = File.CreateText(Path.Combine(path, _logName + "0" + ".log"));
            ((StreamWriter)_logger).AutoFlush = true;
        }

        internal static void Error(Exception ex, string error, params object[] args)
        {
            _logger.WriteLine("*******************************************************");
            _logger.WriteLine(String.Format(error, args));
            _logger.WriteLine(ex);
        }

        internal static void Error(string stack, string error, params object[] args)
        {
            _logger.WriteLine("*******************************************************");
            _logger.WriteLine(String.Format(error, args));
            _logger.WriteLine(stack);
        }

        internal static void Warn(string warning, params object[] args)
        {
            _logger.WriteLine("- - - - - - - - - - - - - - - - - - - - - - - - - - - - ");
            _logger.WriteLine(String.Format(warning, args));
        }

        internal static void Write(string message, params object[] args)
        {
            _logger.WriteLine(String.Format(message, args));
        }

        internal static ILog GetLogger(Type type)
        {
            return new ClassLogger(type);
        }

        internal static Application.LogCallback GetLogCallback(ILog log)
        {
            return (logString, stack, type) =>
            {
                if (type == LogType.Exception)
                {
                    log.Error(stack, logString);
                }
            };
        }
    }

    /// <summary>
    /// Prepends each log message with the sending class.
    /// </summary>
    public class ClassLogger : ILog
    {
        private string _loggingClass;

        public ClassLogger(Type type)
        {
            string prefix = "Assets.Scripts.";
            var typeString = type.ToString().StartsWith(prefix) ? type.ToString().Substring(prefix.Length) : type.ToString();
            _loggingClass = "[" + typeString + "]: ";
            Log.Open();
        }

        public void Error(Exception ex, string error, params object[] args)
        {
            Log.Error(ex, _loggingClass + error, args);
        }

        public void Error(string stack, string error, params object[] args)
        {
            Log.Error(stack, _loggingClass + error, args);
        }

        public void Warn(string warning, params object[] args)
        {
            Log.Warn(_loggingClass + warning, args);
        }

        public void Write(string message, params object[] args)
        {
            Log.Write(_loggingClass + message, args);
        }

    }
}