Add more contextual log printing on missing object/asset reference

#2414
This commit is contained in:
Wojtek Figat
2024-09-15 23:03:53 +02:00
parent 1fa0159079
commit a367d40913
6 changed files with 74 additions and 15 deletions

View File

@@ -7,6 +7,7 @@
#include "Loading/ContentLoadingManager.h"
#include "Loading/Tasks/LoadAssetTask.h"
#include "Engine/Core/Log.h"
#include "Engine/Core/LogContext.h"
#include "Engine/Engine/Engine.h"
#include "Engine/Threading/Threading.h"
#include "Engine/Profiler/ProfilerCPU.h"
@@ -587,9 +588,10 @@ bool Asset::IsInternalType() const
bool Asset::onLoad(LoadAssetTask* task)
{
if (task->Asset.Get() != this || Platform::AtomicRead(&_loadingTask) == 0)
// It may fail when task is cancelled and new one was created later (don't crash but just end with an error)
if (task->Asset.Get() != this || Platform::AtomicRead(&_loadingTask) == 0)
return true;
LogContextScope logContext(GetID());
Locker.Lock();

View File

@@ -9,6 +9,7 @@
#include "Storage/JsonStorageProxy.h"
#include "Factories/IAssetFactory.h"
#include "Engine/Core/Log.h"
#include "Engine/Core/LogContext.h"
#include "Engine/Core/Types/String.h"
#include "Engine/Core/ObjectsRemovalService.h"
#include "Engine/Engine/EngineService.h"
@@ -970,6 +971,7 @@ Asset* Content::LoadAsync(const Guid& id, const ScriptingTypeHandle& type)
if (IsAssetTypeIdInvalid(type, result->GetTypeHandle()) && !result->Is(type))
{
LOG(Warning, "Different loaded asset type! Asset: \'{0}\'. Expected type: {1}", result->ToString(), type.ToString());
LogContext::Print(LogType::Warning);
return nullptr;
}
return result;
@@ -1004,6 +1006,7 @@ Asset* Content::LoadAsync(const Guid& id, const ScriptingTypeHandle& type)
if (!GetAssetInfo(id, assetInfo))
{
LOG(Warning, "Invalid or missing asset ({0}, {1}).", id, type.ToString());
LogContext::Print(LogType::Warning);
LOAD_FAILED();
}
#if ASSETS_LOADING_EXTRA_VERIFICATION

View File

@@ -1,9 +1,15 @@
// Copyright (c) 2012-2024 Wojciech Figat. All rights reserved.
#include "LogContext.h"
#include "Engine/Core/Log.h"
#include "Engine/Core/Types/Guid.h"
#include "Engine/Core/Types/String.h"
#include "Engine/Core/Types/StringBuilder.h"
#include "Engine/Core/Collections/Array.h"
#include "Engine/Scripting/Scripting.h"
#include "Engine/Scripting/Script.h"
#include "Engine/Content/Asset.h"
#include "Engine/Level/Actor.h"
#include "Engine/Threading/ThreadLocal.h"
struct LogContextThreadData
@@ -30,7 +36,7 @@ struct LogContextThreadData
Count--;
}
LogContextData Peek()
LogContextData Peek() const
{
return Count > 0 ? Ptr[Count - 1] : LogContextData();
}
@@ -38,12 +44,54 @@ struct LogContextThreadData
ThreadLocal<LogContextThreadData> GlobalLogContexts;
String LogContext::GetInfo()
void LogContext::Print(LogType verbosity)
{
LogContextData context = LogContext::Get();
if (context.ObjectID != Guid::Empty)
return String::Format(TEXT("(Loading source was {0})"), context.ObjectID);
return String::Empty;
auto& stack = GlobalLogContexts.Get();
if (stack.Count == 0)
return;
const StringView indentation(TEXT(" "));
StringBuilder msg;
for (int32 index = (int32)stack.Count - 1; index >= 0; index--)
{
// Build call hierarchy via indentation
msg.Clear();
for (uint32 i = index; i < stack.Count; i++)
msg.Append(indentation);
LogContextData& context = stack.Ptr[index];
if (context.ObjectID != Guid::Empty)
{
// Object reference context
msg.Append(TEXT(" Referenced by "));
if (ScriptingObject* object = Scripting::TryFindObject(context.ObjectID))
{
const StringAnsiView typeName(object->GetType().Fullname);
if (Asset* asset = ScriptingObject::Cast<Asset>(object))
{
msg.AppendFormat(TEXT("asset '{}' ({}, {})"), asset->GetPath(), asset->GetTypeName(), context.ObjectID);
}
else if (Actor* actor = ScriptingObject::Cast<Actor>(object))
{
msg.AppendFormat(TEXT("actor '{}' ({}, {})"), actor->GetNamePath(), String(typeName), context.ObjectID);
}
else if (Script* script = ScriptingObject::Cast<Script>(object))
{
msg.AppendFormat(TEXT("script '{}' ({}, {})"), script->GetNamePath(), String(typeName), context.ObjectID);
}
else
{
msg.AppendFormat(TEXT("object {} ({})"), String(typeName), context.ObjectID);
}
}
else
{
msg.AppendFormat(TEXT("object {}"), context.ObjectID);
}
}
// Print message
Log::Logger::Write(verbosity, msg.ToStringView());
}
}
void LogContext::Push(const Guid& id)

View File

@@ -9,7 +9,7 @@ class String;
struct Guid;
/// <summary>
/// Log context data structure. Contains different kinds of context data for different situtations.
/// Log context data structure. Contains different kinds of context data for different situations.
/// </summary>
API_STRUCT(NoDefault) struct FLAXENGINE_API LogContextData
{
@@ -54,10 +54,10 @@ API_CLASS(Static) class FLAXENGINE_API LogContext
API_FUNCTION() static LogContextData Get();
/// <summary>
/// Returns a string which represents the current log context on the stack.
/// Prints the current log context to the log. Does nothing it
/// </summary>
/// <returns>The formatted string representing the current log context.</returns>
API_FUNCTION() static String GetInfo();
/// <param name="verbosity">The verbosity of the log.</param>
API_FUNCTION() static void Print(enum class LogType verbosity);
};
/// <summary>

View File

@@ -881,7 +881,8 @@ ScriptingObject* Scripting::FindObject(Guid id, const MClass* type)
// Check type
if (!type || result->Is(type))
return result;
LOG(Warning, "Found scripting object with ID={0} of type {1} that doesn't match type {2}. {3}", id, String(result->GetType().Fullname), String(type->GetFullName()), LogContext::GetInfo());
LOG(Warning, "Found scripting object with ID={0} of type {1} that doesn't match type {2}", id, String(result->GetType().Fullname), String(type->GetFullName()));
LogContext::Print(LogType::Warning);
return nullptr;
}
@@ -900,7 +901,8 @@ ScriptingObject* Scripting::FindObject(Guid id, const MClass* type)
return asset;
}
LOG(Warning, "Unable to find scripting object with ID={0}. Required type {1}. {2}", id, String(type->GetFullName()), LogContext::GetInfo());
LOG(Warning, "Unable to find scripting object with ID={0}. Required type {1}", id, String(type->GetFullName()));
LogContext::Print(LogType::Warning);
return nullptr;
}

View File

@@ -727,7 +727,10 @@ DEFINE_INTERNAL_CALL(MObject*) ObjectInternal_FindObject(Guid* id, MTypeObject*
if (klass && !obj->Is(klass))
{
if (!skipLog)
LOG(Warning, "Found scripting object with ID={0} of type {1} that doesn't match type {2}. {3}", *id, String(obj->GetType().Fullname), String(klass->GetFullName()), LogContext::GetInfo());
{
LOG(Warning, "Found scripting object with ID={0} of type {1} that doesn't match type {2}", *id, String(obj->GetType().Fullname), String(klass->GetFullName()));
LogContext::Print(LogType::Warning);
}
return nullptr;
}
return obj->GetOrCreateManagedInstance();
@@ -736,9 +739,10 @@ DEFINE_INTERNAL_CALL(MObject*) ObjectInternal_FindObject(Guid* id, MTypeObject*
if (!skipLog)
{
if (klass)
LOG(Warning, "Unable to find scripting object with ID={0}. Required type {1}. {2}", *id, String(klass->GetFullName()), LogContext::GetInfo());
LOG(Warning, "Unable to find scripting object with ID={0} of type {1}", *id, String(klass->GetFullName()));
else
LOG(Warning, "Unable to find scripting object with ID={0}", *id);
LogContext::Print(LogType::Warning);
}
return nullptr;
}