Custom Logger - Prostsze zarządzanie logami

Wstęp

Silnik Unity udostępnia statyczną klasę Debug, która zawiera metody ułatwiające śledzenie błędów i analizowanie działania gry podczas jej tworzenia. Wraz ze wzrostem złożoności projektu rośnie również liczba generowanych logów, co może utrudniać efektywne debugowanie. Często zależy nam na analizie konkretnego systemu, bez przeglądania nieistotnych komunikatów z innych części gry. Dlatego możliwość filtrowania i organizowania logów staje się kluczowa, aby utrzymać przejrzystość i kontrolę nad procesem debugowania.

W tym artykule przyjrzymy się następującym zagadnieniom:

• Jak stworzyć własną klasę CustomLogger
• Dlaczego warto używać Debug.LogFormat zamiast Debug.Log
• Jak zarządzać logami za pomocą Scripting Define Symbols
• Dlaczego warto używać atrybutu Conditional

Tworzenie własnego systemu logowania

Tworząc własny wrapper dla Debug.Log, najprostszym rozwiązaniem jakie może przyjść nam do głowy, jest dodawanie prefixów do naszych komunikatów w celu ich kategoryzacji.

Tworzymy więc statyczną metodę, która będzie do każdej wiadomości będzie dodawała np. nazwę modułu gry którego log dotyczy. Dla przykładu stwórzmy więc metodę dla systemu Photo Mode.

Taka metoda może wyglądać następująco:

public static void PhotoModeLog(string message, Object context = null)
{
  Debug.Log("[Photo Mode System]: " + message, context);
}

Nasza nowo utworzona metoda działa dokładnie tak jak Debug.Log zaimplementowane przez Unity. Przyjmuje parametry message oraz opcjonalnie context(Jednak jeżeli chcemy sprawić, by nasze logi były bardziej przydatne, powinniśmy wymusić podawanie contextu naszych logów). Silnik Unity dostarcza 2 przeciążenia metody Log, które prezentują się to następująco:

public static void Log(object message) => Debug.unityLogger.Log(LogType.Log, message);
public static void Log(object message, Object context)
{
  Debug.unityLogger.Log(LogType.Log, message, context);
}

Co oznacza dobry log?

Zatrzymajmy się tutaj na chwilę. Jaką informację chcemy przekazywać i otrzymywać z naszych logów? Jeśli komunikat mówi tylko „Operacja nie powiodła się”, równie dobrze może go w ogóle nie być. Taki komunikat nie przekazuje nam najważniejszych informacji tj. Jaka operacja się nie powiodła, dlaczego tak się stało, w którym miejscu naszego systemu do tego doszło oraz na jakim obiekcie. Dobry log powinien informować, jak usunąć ostrzeżenie/błąd oraz skąd on się wziął.

Finalnie nasza metoda powinna prezentować się następująco:

public static class CustomLogger
{
  public static void PhotoModeLog(string message, Object context)
  {
    Debug.Log("[Camera System]: " + message, context);
  }
}

a tutaj przykładowe użycie loga:

CustomLogger.PhotoModeLog("Message", this.gameObject);

Voilà. Wszystko wydaje się działać poprawnie, jednak czy aby na pewno?

Zwykle gdy w konsoli pojawia się nam jakiś błąd chcemy przenieść się szybko do edytora kodu w miejsce, które spowodowało to wywołanie. Klikamy 2 razy na message i… no właśnie. IDE otwiera się, a my lądujemy nie w miejscu wywołania tylko w naszej statycznej klasie CustomLogger. Unity przeniesie nas do metody PhotoModeLog, ponieważ to tam zostało wykonane logowanie.

Co dalej? - Problem z nawigacją do kodu

Jednym z często proponowanych rozwiązań tego problemu jest zamknięcie klasy CustomLogger w pliku .dll. Pomysł ten polega na tym, że jeśli klasa loggera znajduje się w skompilowanej bibliotece, Unity nie będzie mogło wskazać jej jako źródła loga i automatycznie przeniesie nas do właściwego miejsca wywołania. Dzieje się tak ponieważ Unity gdy nie może dostać się na szczyt stosu (stack trace), przekaże ostatnie miejsce do którego ma dostęp. Choć to rozwiązanie działa, wymaga kilku kroków przy każdej modyfikacji:

• edycji kodu źródłowego biblioteki
• ponownej kompilacji .dll
• ponownego importu .dll do projektu Unity

Dlatego lepszym rozwiązaniem jest użycie metody Debug.LogFormat i stworzenie własnych logów. Debug.LogFormat nie konkatenuje stringów przed wywołaniem – przekazuje je bezpośrednio do Unity. Silnik rozpoznaje miejsce, z którego pochodzi wywołanie loga, nawet jeśli logowanie jest opakowane w statycznej metodzie.

Utwórzmy więc klasę korzystającą z tego rozwiązania. Zawrzyjmy w niej 3 podstawowe typy logowania oferowane przez Unity tj. Log, Warning oraz Error.

public static class CustomLogger
{
  public static void Log(object message, Object context)
  {
    LogMessage(LogType.Log, message, context);
  }

  public static void LogWarning(object message, Object context)
  {
    LogMessage(LogType.Warning, message, context);
  }

  public static void LogError(object message, Object context)
  {
    LogMessage(LogType.Error, message, context);
  }

  private static string FormatMessage(object message)
  {
    return message?.ToString() ?? "NULL";
  }
  private static void LogMessage(LogType logType, object message, Object context)
  {
    if (!Debug.isDebugBuild) return;
    Debug.LogFormat(logType, LogOption.None, context, "{0}", FormatMessage(message));
  }
}

Dla lepszej czytelności wprowadziłem 2 metody prywatne

• FormatMessage – Zapewnia, że każda wiadomość zostanie poprawnie przekonwertowana na string. Jeśli przekazany obiekt jest null, zwraca "NULL", aby uniknąć błędów w logach.

• LogMessage – Główna metoda obsługująca logowanie. Sprawdza, czy gra działa w trybie Debug Build, a następnie loguje wiadomość za pomocą Debug.LogFormat, jeśli flaga zwróciła true.

To wszytko. Teraz Używając CustomLogger.Log() podwójne kliknięcie w konsoli przenosi nas w odpowiednie miejsce w kodzie! 🎯

Kompilacja warunkowa

Nie byłbym sobą gdybyśmy tutaj zakończyli. Nasz CustomLogger możemy ulepszyć wprowadzając kompilacje warunkową. Czasami chcemy wyłączyć logi w produkcji, aby nie obciążały wydajności gry. Flaga Debug.isDebugBuil jest jednym ze sposobów na wyłączenie ich globalnie. Jednak zróbmy to lepiej.

Możemy podzielić nasze logi na kategorię, a użyjemy do tego Scripting Define Symbols oraz atrybutu Atrybut [Conditional]- pozwala on na kompilowanie i wykonywanie kodu tylko wtedy, gdy zdefiniowany jest dany symbol (np. DEBUGGING_MODE).

private const string DEBUGGING_MODE = "DEBUGGING_MODE";

[Conditional(DEBUGGING_MODE)]
public static void Log(object message, Object context)
{
  LogMessage(LogType.Log, message, context);
}

Jak aktywować/dezaktywować logowanie?

• Przejdź do Edit > Project Settings > Player.
• W sekcji Scripting Define Symbols dodaj lub usuń DEBUGGING_MODE
• Po kliknięciu Apply Unity skompiluje kod z aktywnymi symbolami.

Zasada działania jest analogiczna jak w przypadku używania #if Jeżeli klucz znajduje się w Scripting Define Symbol kod jest włączony do kompilacji.

Dlaczego więc nie używam np #if DEBUGGING_MODE oraz #endif w klasie loggera? To rozwiązanie wymagałoby to otaczania także każdego wywołania CustomLogger takimi warunkami. Rozwiązanie to jest mniej odporne na pomyłki, ponieważ błąd kompilacji otrzymujemy tylko w przypadku wyłączenia danego Symbolu. Atrybut Conditional pomija tą niedogodność.

Przykład wywołania loga, gdy Symbol DEBUGGING_MODE jest wyłączony

Finalnie nasza klasa prezentuje się w następujący sposób:

using System.Diagnostics;
using UnityEngine;
using Object = UnityEngine.Object;

namespace Polyphantom.CustomLogger
{
  public static class CustomLogger
  {
    private const string DEBUGGING_MODE = "DEBUGGING_MODE";

    private static string FormatMessage(object message)
    {
      return message?.ToString() ?? "NULL";
    }

    private static void LogMessage(LogType logType, object message, Object context)
    {
      if (!UnityEngine.Debug.isDebugBuild) return;
      UnityEngine.Debug.LogFormat(logType, LogOption.None, context, "{0}", FormatMessage(message));
    }

    [Conditional(DEBUGGING_MODE)]
    public static void Log(object message, Object context = null)
    {
      LogMessage(LogType.Log, message, context);
    }

    [Conditional(DEBUGGING_MODE)]
    public static void LogWarning(object message, Object context = null)
    {
      LogMessage(LogType.Warning, message, context);
    }

    [Conditional(DEBUGGING_MODE)]
    public static void LogError(object message, Object context = null)
    {
      LogMessage(LogType.Error, message, context);
    }
  }
}

Przedstawiony CustomLogger to tylko szablon do zaadaptowania we własnych projektach. Możemy stworzyć wiele kategorii logów, które można aktywować i dezaktywować za pomocą Scripting Define Symbols. Spójrzmy na poniższy przykład:

private const string AI_DEBUG = "AI_DEBUG";
private const string NETWORK_DEBUG = "NETWORK_DEBUG";

[Conditional(AI_DEBUG)]
public static void LogAI(object message, Object context)
{
  LogMessage(LogType.Log, "[AI]: " + message, context);
}

[Conditional(NETWORK_DEBUG)]
public static void LogNetwork(object message, Object context)
{
  LogMessage(LogType.Log, "[NETWORK]: " + message, context);
}

Teraz możemy łatwo włączać i wyłączać określone logi bez zmiany kodu za pomocą AI_DEBUG oraz NETWORK_DEBUG! 💡 Pamiętajcie proces logowania rzeczy do konsoli wpływa na wydajność gry. Wyłączenie zbędnych komunikatów już na etapie kompilacji może okazać się niezwykle pomocne nie tylko do czytelnośći pliku .log ale także dla samego performencu gry.

Zachęcam was do poeksperymentowania i np. dodania kolorowania do słów kluczowych, czy linków w waszych logach. Poniżej przykład edytorowego loga z narzędzia do tworzenia screenshotów. Nazwa utworzonego pliku jest wyróżniona poprzez kolor, a ścieżka do pliku to link który po kliknięciu otwiera folder z screenami. Log pojawia się tylko w edytorze.

Log pochodzący z narzędzia do robienia zrzutów ekranu

To wszystko na dziś, trzymajcie sie i do następnego! 🐍

Przypisy

• Unity - Manual: The Debug class
• Unity - Scripting API: Debug.LogFormat
• Unity - Scripting API: PlayerSettings.SetScriptingDefineSymbols
• ConditionalAttribute Class (System.Diagnostics)