Ue Testing Debugging

UE Testing, Logging & Profiling

Target engine: UE 5.8. APIs below are verified against the 5.8 headers; older forms are listed under "Deprecated — do not use".

This skill owns logging, assertions, automation/functional testing, console commands and performance profiling for the repo. Logging, assertions, stats, trace and CVars live in Core (Logging/, Misc/AssertionMacros.h, Stats/Stats.h, ProfilingDebugging/, HAL/IConsoleManager.h). Debug drawing, the Visual Logger and AHUD::ShowDebug live in Engine. Test frameworks are the developer modules AutomationController, CQTest, FunctionalTesting and AutomationDriver; the Gameplay Debugger is the runtime module GameplayDebugger.

Context

Read .agents/ue-project-context.md if it exists (module names, conventions, enabled plugins, GAS/networking setup). Do not stop if it is missing. Identify the area from the request and the codebase; ask only when two plausible readings would produce different code.

Logging

Declaring categories

#include "Logging/LogMacros.h"
// MyGameLogging.h — DECLARE_LOG_CATEGORY_EXTERN(Name, DefaultVerbosity, CompileTimeVerbosity)
DECLARE_LOG_CATEGORY_EXTERN(LogMyGame, Log, All);

DEFINE_LOG_CATEGORY(LogMyGame);   // MyGameLogging.cpp

DefaultVerbosity must be <= CompileTimeVerbosity or the static_assert inside the category macro fires. Anything above CompileTimeVerbosity is deleted by the compiler, so DECLARE_LOG_CATEGORY_EXTERN(LogMyGame, Log, Log) removes every Verbose/VeryVerbose call site. Monolithic builds can cap all categories at once by defining COMPILED_IN_MINIMUM_VERBOSITY.

Verbosity levels

ELogVerbosity::All is an alias for VeryVerbose and is the usual CompileTimeVerbosity argument.

Emitting

UE_LOG(LogMyGame, Display, TEXT("Player %s spawned"), *PlayerName);
UE_LOG(LogMyGame, Warning, TEXT("Inventory full, dropped %s"), *ItemName);
UE_LOG(LogMyGame, Error,   TEXT("Failed to load asset %s"), *AssetPath);
UE_LOG(LogMyGame, Fatal,   TEXT("Save data unrecoverable"));   // crashes

// Condition and arguments are evaluated only when the category is active.
UE_CLOG(Health <= 0.f, LogMyGame, Warning, TEXT("%s has zero health"), *GetName());

Wrap an expensive report in if (UE_LOG_ACTIVE(LogMyGame, Verbose)) { … } so the work itself is skipped, not just the formatting.

Structured logging

UE_LOGFMT emits named fields that survive into Insights and log analysis; use {Name} placeholders, not %s.

#include "Logging/StructuredLog.h"

// Named fields: order is irrelevant, extra fields are allowed.
UE_LOGFMT(LogMyGame, Warning, "Loading '{Name}' failed with error {Error}",
    ("Name", AssetName), ("Error", ErrorCode), ("Flags", LoadFlags));

// Positional fields: the values must match the placeholders exactly.
UE_LOGFMT(LogMyGame, Display, "Spawned {Count} actors in {Seconds}s", SpawnCount, Elapsed);
UE_CLOGFMT(bFailed, LogMyGame, Error, "Retry {Attempt} failed", ("Attempt", Attempt));

Field names must match [A-Za-z0-9_]+ and be unique per event; values serialize through SerializeForLog or operator<<(FCbWriter&, T). UE_LOGFMT takes at most 16 fields — use UE_LOGFMT_EX with UE_LOGFMT_FIELD / UE_LOGFMT_VALUE beyond that.

Shipping and Test builds

NO_LOGGING is !USE_LOGGING_IN_SHIPPING in both Test and Shipping, and 0 in Debug and Development. Under NO_LOGGING, UE_LOG/UE_CLOG/UE_LOGFMT collapse to a Fatal-only path: every non-fatal call disappears, arguments included. Set bUseLoggingInShipping = true; in MyGame.Target.cs to define USE_LOGGING_IN_SHIPPING=1 and get logging back.

Controlling verbosity at runtime

-LogCmds="LogMyGame Verbose, LogNet Warning"   # command line, applied at boot
Log list [Filter]       # every category with its current verbosity
Log LogMyGame Verbose   # raise one category
Log global none         # silence everything
Log reset               # restore defaults

From code use UE_SET_LOG_VERBOSITY(LogMyGame, Verbose); from config use [Core.Log] in DefaultEngine.ini.

Assertions

All in Misc/AssertionMacros.h. Choose by who is wrong: check for programmer error, ensure for a recoverable surprise worth reporting, a plain if for user or data input.

check(Component != nullptr);
checkf(Index >= 0 && Index < Items.Num(), TEXT("Index %d out of [0,%d)"), Index, Items.Num());
checkNoEntry();                             // unreachable branch
checkNoReentry();                           // must not be entered twice
checkSlow(ValidateExpensiveInvariant());    // Debug only
verify(Manager->Initialize());              // expression ALWAYS evaluated

if (ensure(Component != nullptr))
{
    Component->Activate();                  // ensure() returns the condition
}
ensureMsgf(Health > 0.f, TEXT("%s has health %.1f"), *GetName(), Health);
ensureAlways(bInitialized);                 // reports every failure, not just the first

ensure/ensureMsgf report once per call site per session; ensureAlways/ensureAlwaysMsgf report every time. All four return the condition, so they compose with if.

USE_CHECKS_IN_SHIPPING defaults to 0 and is set by bUseChecksInShipping in the target rules, so Test builds also strip check and ensure by default. When DO_CHECK is 0, check(expr) degrades to CA_ASSUME(expr) and the expression is never evaluated; verify(expr) still evaluates it and only drops the halt.

Automation Tests

Test sources live in a Private/Tests folder of the module under test, or in a dedicated test module. Wrap each test file in #if WITH_DEV_AUTOMATION_TESTS (or WITH_AUTOMATION_TESTS = WITH_DEV_AUTOMATION_TESTS || WITH_PERF_AUTOMATION_TESTS) — the IMPLEMENT_* macros alone still compile the class, they only skip registration when WITH_AUTOMATION_WORKER is 0 (Misc/AutomationTest.h:4366); UBT turns both on for every configuration except Test and Shipping, overridable with bForceCompileDevelopmentAutomationTests, bForceCompilePerformanceAutomationTests and bForceDisableAutomationTests (UEBuildTarget.cs:6309-6325). Module and target wiring, the full pattern library and the command lines for running tests are in references/automation-test-patterns.md.

// Source/MyGame/Private/Tests/MyInventoryTest.cpp — whole file inside #if WITH_DEV_AUTOMATION_TESTS
#include "Misc/AutomationTest.h"
#include "MyInventoryComponent.h"

IMPLEMENT_SIMPLE_AUTOMATION_TEST(FMyInventoryAddTest, "MyGame.Inventory.AddItem",
    EAutomationTestFlags::EditorContext | EAutomationTestFlags::ProductFilter)

bool FMyInventoryAddTest::RunTest(const FString& Parameters)
{
    UMyInventoryComponent* Inv = NewObject<UMyInventoryComponent>(GetTransientPackage());
    UE_RETURN_ON_ERROR(Inv != nullptr, TEXT("Inventory created"));

    Inv->AddItem(FName("Sword"), 1);
    TestEqual(TEXT("Count after add"), Inv->GetItemCount(FName("Sword")), 1);
    TestTrue(TEXT("Has sword"), Inv->HasItem(FName("Sword")));
    TestFalse(TEXT("No axe"), Inv->HasItem(FName("Axe")));
    return true;
}

IMPLEMENT_COMPLEX_AUTOMATION_TEST adds virtual void GetTests(TArray<FString>& OutBeautifiedNames, TArray<FString>& OutTestCommands) const and runs RunTest once per entry. IMPLEMENT_CUSTOM_SIMPLE_AUTOMATION_TEST(TClass, TBaseClass, PrettyName, TFlags) declares a simple test whose base is a shared fixture you derive from FAutomationTestBase.

Flags

EAutomationTestFlags is an enum class with ENUM_CLASS_FLAGS, so combine with |. Two static_asserts enforce at least one context flag and exactly one filter flag.

EAutomationTestFlags_ApplicationContextMask covers every context flag in one token.

Assertions inside a test

TestEqual(TEXT("Label"), Actual, Expected);              // int32/int64/SIZE_T/FName/FText/FString/FStringView…
TestEqual(TEXT("Approx"), ActualF, ExpectedF, 0.001f);   // float/double/FVector/FRotator/FTransform take a tolerance
TestTrue(TEXT("Label"), bCondition);                     // also TestFalse, TestNotEqual
TestNotNull(TEXT("Label"), Ptr);                         // also TestNull, TestSamePtr, TestNotSamePtr
TestValid(TEXT("Label"), SharedOrWeakPtr);               // also TestInvalid

AddError(FString::Printf(TEXT("Unexpected damage %d"), Damage));   // also AddWarning, AddInfo
AddErrorIfFalse(bOk, TEXT("Setup failed"));
UE_RETURN_ON_ERROR(Ptr != nullptr, TEXT("Ptr must not be null")); // adds error, returns false

// Expect (and swallow) a log line the code under test is supposed to emit.
AddExpectedMessage(TEXT("Inventory is full"), ELogVerbosity::Warning,
                   EAutomationExpectedMessageFlags::Contains);

The pattern is a regex unless you use the …Plain variants (AddExpectedMessagePlain, AddExpectedErrorPlain). AddExpectedError(Pattern, MatchType, Occurrences, bIsRegex) is the shorthand that matches warnings and errors (it forwards ELogVerbosity::Warning, which is inclusive); the AddExpectedMessage overload without a verbosity matches every severity.

Latent commands

RunTest returns before latent commands run. Enqueue them, then let Update() return true when the step is finished. Enqueuing after return true; is unreachable code.

DEFINE_LATENT_AUTOMATION_COMMAND_ONE_PARAMETER(FMyWaitSecondsCommand, float, Duration);
bool FMyWaitSecondsCommand::Update()
{
    return GetCurrentRunTime() >= Duration;
}

ADD_LATENT_AUTOMATION_COMMAND(FMyWaitSecondsCommand(2.0f));   // inside RunTest, before `return true;`

DEFINE_LATENT_AUTOMATION_COMMAND through ..._FIVE_PARAMETER exist. To assert after the wait, derive from IAutomationLatentCommand and capture the FAutomationTestBase*.

Specs

BEGIN_DEFINE_SPEC(TClass, PrettyName, TFlags) / member declarations / END_DEFINE_SPEC(TClass) declares a BDD-style test whose body is void TClass::Define(). Inside Define() use Describe, It, LatentIt, BeforeEach, LatentBeforeEach, AfterEach (and xIt/xDescribe to disable a block). DEFINE_SPEC(TClass, PrettyName, TFlags) replaces the pair when the spec needs no members. Worked example in references/automation-test-patterns.md.

CQTest

CQTest (module CQTest) is the fixture-based front end over the same framework. Assert is a FNoDiscardAsserter, so every assertion goes through ASSERT_THAT, which returns from the method on failure.

#include "CQTest.h"

TEST_CLASS(FMyInventoryTests, "MyGame.Inventory")
{
    UMyInventoryComponent* Inventory = nullptr;

    BEFORE_EACH() { Inventory = NewObject<UMyInventoryComponent>(GetTransientPackage()); }

    TEST_METHOD(AddItem_WhenEmpty_StoresOne)
    {
        Inventory->AddItem(FName("Sword"), 1);
        ASSERT_THAT(AreEqual(1, Inventory->GetItemCount(FName("Sword"))));
    }

    TEST_METHOD_WITH_TAGS(AddItem_WhenFull_Rejects, "[Slow][Inventory]")
    {
        Inventory->SetCapacity(0);
        ASSERT_THAT(IsFalse(Inventory->AddItem(FName("Sword"), 1)));
    }
};

TEST_CLASS(ClassName, TestDir) uses FNoDiscardAsserter and DefaultFlags (EAutomationTestFlags_ApplicationContextMask | EAutomationTestFlags::ProductFilter). Variants: TEST_CLASS_WITH_FLAGS(ClassName, TestDir, Flags), TEST_CLASS_WITH_TAGS, TEST_CLASS_WITH_BASE, TEST_CLASS_WITH_ASSERTS. Lifecycle macros are BEFORE_ALL()/AFTER_ALL() (static, once per fixture) and BEFORE_EACH()/AFTER_EACH() (override Setup()/TearDown()). Asserter helpers: IsTrue, IsFalse, IsNull, IsNotNull, AreEqual, AreNotEqual, AreEqualIgnoreCase, AreNotEqualIgnoreCase, IsNear(Expected, Actual, Epsilon) — each also takes a trailing failure message.

World, actor and async helpers (TestCommandBuilder, FSpawnHelper, FActorTestSpawner, FMapTestSpawner, TObjectBuilder, UTestGameInstance) are covered in references/automation-test-patterns.md.

Functional Tests

AFunctionalTest (module FunctionalTesting) is an actor placed in a test map. PrepareTest, StartTest, IsReady_Implementation and OnTimeout are protected virtuals; FinishTest and the Assert* helpers are public.

// MyFunctionalTest.h
#pragma once
#include "CoreMinimal.h"
#include "FunctionalTest.h"
#include "MyFunctionalTest.generated.h"

UCLASS()
class MYGAME_API AMyFunctionalTest : public AFunctionalTest
{
    GENERATED_BODY()

protected:
    // PrepareTest() sets TimeLimit / PreparationTimeLimit; IsReady_Implementation()
    // gates StartTest(); StartTest() asserts and calls FinishTest().
    virtual void PrepareTest() override;
    virtual bool IsReady_Implementation() override;
    virtual void StartTest() override;

private:
    UPROPERTY(EditInstanceOnly, Category = "MyGame")
    TObjectPtr<AActor> TargetActor;
};

Each override calls Super:: first. FinishTest(EFunctionalTestResult TestResult, const FString& Message) ends the run; EFunctionalTestResult is Default, Invalid, Error, Running, Failed, Succeeded, and Default lets the recorded assertions decide. Assertions are AssertTrue/AssertFalse (bool Condition, const FString& Message, const UObject* ContextObject = nullptr), AssertIsValid(UObject*, const FString&, const UObject* = nullptr), AssertEqual_Int/Float/Bool/Name/Object/Vector/Rotator/Transform/Quat and AssertValue_Int/Float/Double/DateTime (with an EComparisonMethod). Also TimeLimit, PreparationTimeLimit, SetTimeLimit(float, EFunctionalTestResult), LogMessage(const FString&) and StartStep/FinishStep. Full .cpp in references/automation-test-patterns.md.

Run every functional test in the current world with the Blueprint node UFunctionalTestingManager::RunAllFunctionalTests(WorldContextObject, bNewLog, bRunLooped, FailedTestsReproString) (the class is MinimalAPI and the function is not FUNCTIONALTESTING_API, so calling it from another module's C++ does not link), or from the command line:

UnrealEditor-Cmd.exe MyGame.uproject -ExecCmds="Automation RunTests MyGame.Functional" -unattended -nopause -testexit="Automation Test Queue Empty" -log

Automation also accepts List, RunTest, RunFilter <Filter>, RunAll, SetFilter, SetPriority, SetMinimumPriority, Quit and SoftQuit; chain them with ;.

Profiling

Full command tables, the CSV and LLM workflows and the bottleneck-triage procedure are in references/profiling-commands.md.

Unreal Insights

# Capture at launch
UnrealEditor.exe MyGame.uproject -trace=cpu,frame,bookmark,counters,gpu,loadtime,log -tracehost=127.0.0.1
UnrealEditor.exe MyGame.uproject -trace=cpu,frame -tracefile=MyCapture.utrace

# Or from the console, mid-session
Trace.File D:/Captures/Run1.utrace cpu,frame,bookmark    # or Trace.Send 127.0.0.1 cpu,frame
Trace.Enable counters
Trace.Bookmark WaveStarted
Trace.Stop                    # also Trace.Pause, Trace.Resume, Trace.Status

Channel names drop the Channel suffix and lowercase: cpu, gpu, frame, bookmark, counters, log, loadtime, task, memalloc, callstack, module, metadata, net, rhicommands, rendercommands, slate, assetmetadata, iostore, animation, region, screenshot.

Instrumenting code

#include "Stats/Stats.h"                              // DECLARE_*_STAT, SCOPE_CYCLE_COUNTER
#include "HAL/PlatformMisc.h"                         // SCOPED_NAMED_EVENT
#include "ProfilingDebugging/CpuProfilerTrace.h"      // TRACE_CPUPROFILER_EVENT_SCOPE
#include "ProfilingDebugging/MiscTrace.h"             // TRACE_BOOKMARK
#include "ProfilingDebugging/CountersTrace.h"         // TRACE_*_COUNTER, TRACE_INT_VALUE
#include "ProfilingDebugging/CsvProfiler.h"           // CSV_*
#include "ProfilingDebugging/ScopedTimers.h"          // FScopedDurationTimer

DECLARE_STATS_GROUP(TEXT("MyGame"), STATGROUP_MyGame, STATCAT_Advanced);
DECLARE_CYCLE_STAT(TEXT("MyGame Tick"), STAT_MyGameTick, STATGROUP_MyGame);
CSV_DEFINE_CATEGORY(MyGame, true);
TRACE_DECLARE_INT_COUNTER(MyGameActiveEnemies, TEXT("MyGame/ActiveEnemies"));

void UMySubsystem::Tick(float DeltaTime)
{
    SCOPE_CYCLE_COUNTER(STAT_MyGameTick);              // stat system + Insights
    TRACE_CPUPROFILER_EVENT_SCOPE(UMySubsystem::Tick); // Insights only, very cheap
    CSV_SCOPED_TIMING_STAT(MyGame, SubsystemTick);     // one CSV column
    SCOPED_NAMED_EVENT(MyGame_Tick, FColor::Orange);   // also visible to PIX/Razor

    TRACE_COUNTER_SET(MyGameActiveEnemies, ActiveEnemyCount);
    CSV_CUSTOM_STAT(MyGame, Enemies, ActiveEnemyCount, ECsvCustomStatOp::Set);
}

void UMySubsystem::BeginWave(int32 WaveNumber)
{
    TRACE_BOOKMARK(TEXT("WaveStarted_%d"), WaveNumber);  // vertical marker in Insights
    CSV_EVENT(MyGame, TEXT("WaveStarted"));

    double LoadSeconds = 0.0;
    {
        FScopedDurationTimer Timer(LoadSeconds);        // accumulates into LoadSeconds
        LoadWaveAssets(WaveNumber);
    }
    UE_LOGFMT(LogMyGame, Display, "Wave {Wave} loaded in {Seconds}s",
        ("Wave", WaveNumber), ("Seconds", LoadSeconds));
}

QUICK_SCOPE_CYCLE_COUNTER(STAT_MyAdHocScope) declares a stat inline for a one-off measurement; TRACE_INT_VALUE(TEXT("MyGame/Spawned"), Count) and TRACE_FLOAT_VALUE emit a counter with no declaration; SCOPED_NAMED_EVENT_TEXT("Name", FColor::Yellow) takes a literal and SCOPED_NAMED_EVENT_F formats one.