LifePlay-Revival/Source/LifePlay/LPSessionLogSubsystem.cpp

// Portage UE 5.5 - lot L3 (journalisation). Voir LPSessionLogSubsystem.h.

#include "LPSessionLogSubsystem.h"

#include "LifePlay.h"
#include "GeneralProjectSettings.h"
#include "HAL/FileManager.h"
#include "HAL/IConsoleManager.h"
#include "Engine/GameInstance.h"
#include "Misc/App.h"
#include "Misc/CommandLine.h"
#include "Misc/Parse.h"
#include "UObject/UnrealType.h"
#include "UObject/Script.h"
#include "UObject/Stack.h"
#include "Blueprint/BlueprintExceptionInfo.h"
#include "Misc/EngineVersion.h"
#include "Misc/OutputDevice.h"
#include "Misc/Paths.h"
#include "Misc/ScopeLock.h"
#include "Containers/Ticker.h"

namespace
{
	// Au-dela, les nouvelles signatures sont comptees ensemble : la memoire reste bornee
	// meme si un Blueprint emet des messages tous differents pendant des heures.
	constexpr int32 MaxSignatures = 4000;
	constexpr int32 SignatureLength = 240;
	constexpr int32 TopSignatures = 25;

	// Remplace chaque suite de chiffres par '#' : "Person_C_2147482340" et
	// "index 12 ... length 12" se regroupent sous une seule signature. Les sauts de ligne
	// deviennent " | " : la pile d'appel Blueprint ("Script call stack:") reste lisible.
	FString MakeSignature(const TCHAR* Message)
	{
		FString Out;
		Out.Reserve(SignatureLength);
		bool bInDigits = false;
		for (const TCHAR* C = Message; *C && Out.Len() < SignatureLength; ++C)
		{
			if (*C == TEXT('\r') || *C == TEXT('\n') || *C == TEXT('\t'))
			{
				if (!Out.EndsWith(TEXT(" | ")) && !Out.IsEmpty()) { Out += TEXT(" | "); }
				bInDigits = false;
			}
			else if (FChar::IsDigit(*C))
			{
				if (!bInDigits) { Out.AppendChar(TEXT('#')); }
				bInDigits = true;
			}
			else
			{
				Out.AppendChar(*C);
				bInDigits = false;
			}
		}
		return Out;
	}

	// Une seule commande console pour le processus, portee par la premiere instance de jeu
	// (en PIE plusieurs GameInstances peuvent coexister).
	FAutoConsoleCommand* SummaryCommand = nullptr;
	const void* SummaryCommandOwner = nullptr;
}

/** Compte les messages du journal. N'ecrit jamais dans le journal lui-meme. */
class FLPLogCounter : public FOutputDevice
{
public:
	virtual void Serialize(const TCHAR* V, ELogVerbosity::Type Verbosity, const FName& Category) override
	{
		const ELogVerbosity::Type Level = (ELogVerbosity::Type)(Verbosity & ELogVerbosity::VerbosityMask);
		if (Category == LogLifePlay.GetCategoryName())
		{
			return;
		}

		FScopeLock Lock(&Mutex);
		++PerCategory.FindOrAdd(FString::Printf(TEXT("%s %s"), *Category.ToString(), ToString(Level)));

		if (Level <= ELogVerbosity::Warning)
		{
			const FString Key = FString::Printf(TEXT("[%s %s] %s"), *Category.ToString(), ToString(Level), *MakeSignature(V));
			if (int32* Count = Signatures.Find(Key))
			{
				++*Count;
			}
			else if (Signatures.Num() < MaxSignatures)
			{
				Signatures.Add(Key, 1);
			}
			else
			{
				++Overflow;
			}
		}
	}

	virtual bool CanBeUsedOnAnyThread() const override { return true; }
	virtual bool CanBeUsedOnMultipleThreads() const override { return true; }

	void Snapshot(TArray<TPair<FString, int32>>& OutCategories, TArray<TPair<FString, int32>>& OutSignatures, int32& OutOverflow) const
	{
		FScopeLock Lock(&Mutex);
		for (const auto& It : PerCategory) { OutCategories.Emplace(It.Key, It.Value); }
		for (const auto& It : Signatures) { OutSignatures.Emplace(It.Key, It.Value); }
		OutOverflow = Overflow;
	}

private:
	mutable FCriticalSection Mutex;
	TMap<FString, int32> PerCategory;
	TMap<FString, int32> Signatures;
	int32 Overflow = 0;
};

/** Repere un motif dans le journal et planifie un releve sur le fil de jeu. N'ecrit jamais dans le journal. */
class FLPLogTrigger : public FOutputDevice
{
public:
	FLPLogTrigger(const FString& InPattern, int32 InMax, TFunction<void(int32, const FString&)> InOnMatch)
		: Pattern(InPattern), Max(InMax), OnMatch(MoveTemp(InOnMatch)) {}

	virtual void Serialize(const TCHAR* V, ELogVerbosity::Type Verbosity, const FName& Category) override
	{
		if (Category == LogLifePlay.GetCategoryName() || !FCString::Strstr(V, *Pattern))
		{
			return;
		}
		FScopeLock Lock(&Mutex);
		const double Now = FPlatformTime::Seconds();
		if (Count >= Max || Now - Last < 5.0)
		{
			return;
		}
		Last = Now;
		const int32 Index = ++Count;
		const FString Line(V);
		// Releve differe : le Blueprint a le temps de terminer l'habillage, et on quitte le journal.
		FTSTicker::GetCoreTicker().AddTicker(FTickerDelegate::CreateLambda([OnMatch = OnMatch, Index, Line](float)
			{
				OnMatch(Index, Line);
				return false;
			}), 1.5f);
	}

	virtual bool CanBeUsedOnAnyThread() const override { return true; }
	virtual bool CanBeUsedOnMultipleThreads() const override { return true; }

private:
	FCriticalSection Mutex;
	FString Pattern;
	int32 Max = 20;
	int32 Count = 0;
	double Last = -1000.0;
	TFunction<void(int32, const FString&)> OnMatch;
};

void ULPSessionLogSubsystem::Initialize(FSubsystemCollectionBase& Collection)
{
	Super::Initialize(Collection);

	StartTime = FPlatformTime::Seconds();
	Counter = MakeShared<FLPLogCounter>();
	GLog->AddOutputDevice(Counter.Get());

	if (!SummaryCommand)
	{
		SummaryCommand = new FAutoConsoleCommand(
			TEXT("LifePlay.LogSummary"),
			TEXT("Ecrit dans le journal le bilan de session LifePlay (messages par categorie, signatures les plus frequentes)."),
			FConsoleCommandDelegate::CreateWeakLambda(this, [this]() { LogSessionSummary(); }));
		SummaryCommandOwner = this;
	}

	LogStartupSummary();
	DumpRequestedVariables(TEXT("demarrage"));
	StartScriptExceptionTrace();
	StartLogTriggeredDump();
}

namespace
{
	/** Type lisible d'une propriete (nom de structure pour les structures et tableaux de structures). */
	FString TraceTypeName(const FProperty* Prop)
	{
		FString TypeName = Prop->GetCPPType();
		if (const FStructProperty* SP = CastField<FStructProperty>(Prop)) { TypeName = SP->Struct->GetName(); }
		if (const FArrayProperty* AP = CastField<FArrayProperty>(Prop))
		{
			if (const FStructProperty* ISP = CastField<FStructProperty>(AP->Inner)) { TypeName = TEXT("TArray<") + ISP->Struct->GetName() + TEXT(">"); }
		}
		return TypeName;
	}

	/** Ecrit les variables locales d'un cadre dont le nom ou le type contient l'un des mots. */
	void TraceFrameLocals(int32 Index, int32 Level, const FFrame& Frame, const TArray<FString>& Keywords)
	{
		if (!Frame.Node || !Frame.Locals)
		{
			return;
		}
		int32 Shown = 0;
		for (TFieldIterator<FProperty> It(Frame.Node); It && Shown < 200; ++It)
		{
			const FProperty* Prop = *It;
			const FString TypeName = TraceTypeName(Prop);
			const FString PropName = Prop->GetName();
			const bool bMatch = Keywords.ContainsByPredicate([&](const FString& K)
				{ return PropName.Contains(K) || TypeName.Contains(K); });
			if (!bMatch)
			{
				continue;
			}
			FString Value;
			Prop->ExportTextItem_Direct(Value, Prop->ContainerPtrToValuePtr<void>(Frame.Locals), nullptr, nullptr, PPF_None);
			UE_LOG(LogLifePlay, Warning, TEXT("[trace %d] %s%s (%s) = %s"), Index,
				Level == 0 ? TEXT("  ") : *FString::Printf(TEXT("  [appelant %d %s] "), Level, *Frame.Node->GetName()),
				*PropName, *TypeName, *Value.Left(500));
			++Shown;
		}
	}
}

void ULPSessionLogSubsystem::StartScriptExceptionTrace()
{
	FString Filter;
	if (!FParse::Value(FCommandLine::Get(), TEXT("LPTraceScriptEx="), Filter, false) || Filter.IsEmpty())
	{
		return;
	}
	FString LocalsList;
	FParse::Value(FCommandLine::Get(), TEXT("LPTraceLocals="), LocalsList, false);
	TArray<FString> Keywords;
	LocalsList.ParseIntoArray(Keywords, TEXT(","), true);
	int32 Max = 3;
	FParse::Value(FCommandLine::Get(), TEXT("LPTraceMax="), Max);

	// Lot L7i : filtre sur la fonction fautive, cadres appelants et variables de l'instance de jeu.
	FString FunctionsList;
	FParse::Value(FCommandLine::Get(), TEXT("LPTraceFunctions="), FunctionsList, false);
	TArray<FString> Functions;
	FunctionsList.ParseIntoArray(Functions, TEXT(","), true);
	int32 Depth = 0;
	FParse::Value(FCommandLine::Get(), TEXT("LPTraceDepth="), Depth);
	FString GIVarsList;
	FParse::Value(FCommandLine::Get(), TEXT("LPTraceGIVars="), GIVarsList, false);
	TArray<FString> GIVars;
	GIVarsList.ParseIntoArray(GIVars, TEXT(","), true);
	const TWeakObjectPtr<UGameInstance> WeakGI = GetGameInstance();

	UE_LOG(LogLifePlay, Display, TEXT("Trace des exceptions de script : filtre '%s', fonctions [%s], variables [%s], %d cadre(s) appelant(s), variables GI [%s], %d releve(s) au plus"),
		*Filter, *FunctionsList, *LocalsList, Depth, *GIVarsList, Max);

	TSharedRef<int32> Count = MakeShared<int32>(0);
	ScriptExceptionHandle = FBlueprintCoreDelegates::OnScriptException.AddLambda(
		[Filter, Keywords, Max, Count, Functions, Depth, GIVars, WeakGI](const UObject* ActiveObject, const FFrame& StackFrame, const FBlueprintExceptionInfo& Info)
		{
			// Brancher un ecouteur supprime la pile d'appel que le moteur ecrit d'ordinaire :
			// on la reecrit pour toutes les exceptions, pas seulement celles relevees.
			const FString StackTrace = StackFrame.GetStackTrace();
			UE_LOG(LogScript, Warning, TEXT("%s"), *StackTrace);

			const FString Description = Info.GetDescription().ToString();
			if (*Count >= Max || !Description.Contains(Filter) || !StackFrame.Node || !StackFrame.Locals)
			{
				return;
			}
			if (Functions.Num() > 0 && !Functions.Contains(StackFrame.Node->GetName()))
			{
				return;
			}
			++*Count;

			UE_LOG(LogLifePlay, Warning, TEXT("[trace %d/%d] %s | objet %s | fonction %s | offset %d"),
				*Count, Max, *Description, *GetNameSafe(ActiveObject), *StackFrame.Node->GetName(),
				StackFrame.Code && StackFrame.Node->Script.Num() ? (int32)(StackFrame.Code - StackFrame.Node->Script.GetData()) : -1);

			TraceFrameLocals(*Count, 0, StackFrame, Keywords);
			const FFrame* Caller = StackFrame.PreviousFrame;
			for (int32 Level = 1; Level <= Depth && Caller; ++Level, Caller = Caller->PreviousFrame)
			{
				TraceFrameLocals(*Count, Level, *Caller, Keywords);
			}

			if (const UGameInstance* GI = WeakGI.Get())
			{
				for (const FString& Name : GIVars)
				{
					const FProperty* Prop = GI->GetClass()->FindPropertyByName(FName(*Name));
					FString Value = TEXT("<introuvable>");
					if (Prop)
					{
						Value.Reset();
						Prop->ExportTextItem_Direct(Value, Prop->ContainerPtrToValuePtr<void>(GI), nullptr, const_cast<UGameInstance*>(GI), PPF_None);
					}
					UE_LOG(LogLifePlay, Warning, TEXT("[trace %d]   GI.%s = %s"), *Count, *Name, *Value.Left(300));
				}
			}
		});
}

void ULPSessionLogSubsystem::DumpRequestedVariables(const TCHAR* When) const
{
	FString List;
	if (!FParse::Value(FCommandLine::Get(), TEXT("LPDumpVars="), List, false))
	{
		return;
	}
	const UGameInstance* GI = GetGameInstance();
	if (!GI)
	{
		return;
	}

	TArray<FString> Names;
	List.ParseIntoArray(Names, TEXT(","), true);
	for (const FString& Name : Names)
	{
		const FProperty* Prop = GI->GetClass()->FindPropertyByName(FName(*Name));
		if (!Prop)
		{
			UE_LOG(LogLifePlay, Warning, TEXT("[dump %s] %s : variable introuvable sur %s"), When, *Name, *GI->GetClass()->GetName());
			continue;
		}

		if (const FArrayProperty* ArrayProp = CastField<FArrayProperty>(Prop))
		{
			FScriptArrayHelper Helper(ArrayProp, ArrayProp->ContainerPtrToValuePtr<void>(GI));
			UE_LOG(LogLifePlay, Display, TEXT("[dump %s] %s : %d element(s)"), When, *Name, Helper.Num());
			for (int32 i = 0; i < Helper.Num(); ++i)
			{
				FString Text;
				ArrayProp->Inner->ExportTextItem_Direct(Text, Helper.GetRawPtr(i), nullptr, const_cast<UGameInstance*>(GI), PPF_None);
				UE_LOG(LogLifePlay, Display, TEXT("[dump %s] %s[%d] = %s"), When, *Name, i, *Text.Left(600));
			}
		}
		else
		{
			FString Text;
			Prop->ExportTextItem_Direct(Text, Prop->ContainerPtrToValuePtr<void>(GI), nullptr, const_cast<UGameInstance*>(GI), PPF_None);
			UE_LOG(LogLifePlay, Display, TEXT("[dump %s] %s = %s"), When, *Name, *Text.Left(600));
		}
	}
}

void ULPSessionLogSubsystem::StartLogTriggeredDump()
{
	FString Pattern;
	if (!FParse::Value(FCommandLine::Get(), TEXT("LPDumpOnLog="), Pattern, false) || Pattern.IsEmpty())
	{
		return;
	}
	FString Paths;
	FParse::Value(FCommandLine::Get(), TEXT("LPDumpPaths="), Paths, false);
	Paths.ParseIntoArray(DumpPathList, TEXT(","), true);
	int32 Max = 20;
	FParse::Value(FCommandLine::Get(), TEXT("LPDumpMax="), Max);

	UE_LOG(LogLifePlay, Display, TEXT("Releve sur motif du journal : '%s', chemins [%s], %d releve(s) au plus"), *Pattern, *Paths, Max);

	TWeakObjectPtr<ULPSessionLogSubsystem> WeakThis(this);
	Trigger = MakeShared<FLPLogTrigger>(Pattern, Max, [WeakThis](int32 Index, const FString& Line)
		{
			if (const ULPSessionLogSubsystem* Self = WeakThis.Get())
			{
				Self->DumpPaths(Index, Line);
			}
		});
	GLog->AddOutputDevice(Trigger.Get());
}

void ULPSessionLogSubsystem::DumpPaths(int32 Index, const FString& Line) const
{
	UE_LOG(LogLifePlay, Warning, TEXT("[releve %d] declencheur : %s"), Index, *Line.Left(300));
	UObject* Root = GetGameInstance();
	for (const FString& Path : DumpPathList)
	{
		TArray<FString> Parts;
		Path.ParseIntoArray(Parts, TEXT("."), true);
		const UObject* Obj = Root;
		FString Value = TEXT("<introuvable>");
		for (int32 i = 0; i < Parts.Num() && Obj; ++i)
		{
			const FProperty* Prop = Obj->GetClass()->FindPropertyByName(FName(*Parts[i]));
			if (!Prop)
			{
				Value = FString::Printf(TEXT("<%s introuvable sur %s>"), *Parts[i], *Obj->GetClass()->GetName());
				break;
			}
			const void* Ptr = Prop->ContainerPtrToValuePtr<void>(Obj);
			if (i + 1 < Parts.Num())
			{
				const FObjectPropertyBase* ObjProp = CastField<FObjectPropertyBase>(Prop);
				Obj = ObjProp ? ObjProp->GetObjectPropertyValue(Ptr) : nullptr;
				if (!Obj)
				{
					Value = FString::Printf(TEXT("<%s vaut None>"), *Parts[i]);
				}
				continue;
			}
			Value.Reset();
			if (const FArrayProperty* ArrayProp = CastField<FArrayProperty>(Prop))
			{
				FScriptArrayHelper Helper(ArrayProp, Ptr);
				UE_LOG(LogLifePlay, Warning, TEXT("[releve %d]   %s : %d element(s)"), Index, *Path, Helper.Num());
				for (int32 j = 0; j < Helper.Num() && j < 120; ++j)
				{
					FString Item;
					ArrayProp->Inner->ExportTextItem_Direct(Item, Helper.GetRawPtr(j), nullptr, const_cast<UObject*>(Obj), PPF_None);
					UE_LOG(LogLifePlay, Warning, TEXT("[releve %d]   %s[%d] = %s"), Index, *Path, j, *Item.Left(700));
				}
				Value = TEXT("");
				break;
			}
			Prop->ExportTextItem_Direct(Value, Ptr, nullptr, const_cast<UObject*>(Obj), PPF_None);
		}
		if (!Value.IsEmpty())
		{
			UE_LOG(LogLifePlay, Warning, TEXT("[releve %d]   %s = %s"), Index, *Path, *Value.Left(700));
		}
	}
}

void ULPSessionLogSubsystem::Deinitialize()
{
	if (Trigger.IsValid())
	{
		GLog->RemoveOutputDevice(Trigger.Get());
		GLog->Flush();
		Trigger.Reset();
	}
	DumpRequestedVariables(TEXT("fin"));
	if (ScriptExceptionHandle.IsValid())
	{
		FBlueprintCoreDelegates::OnScriptException.Remove(ScriptExceptionHandle);
		ScriptExceptionHandle.Reset();
	}
	LogSessionSummary();

	if (Counter.IsValid())
	{
		GLog->RemoveOutputDevice(Counter.Get());
		// Un autre thread peut encore etre dans Serialize : on vide la file avant liberation.
		GLog->Flush();
		Counter.Reset();
	}
	if (SummaryCommandOwner == this)
	{
		delete SummaryCommand;
		SummaryCommand = nullptr;
		SummaryCommandOwner = nullptr;
	}

	Super::Deinitialize();
}

void ULPSessionLogSubsystem::LogStartupSummary() const
{
	const UGeneralProjectSettings* Project = GetDefault<UGeneralProjectSettings>();
	UE_LOG(LogLifePlay, Display, TEXT("===== LifePlay : demarrage ====="));
	UE_LOG(LogLifePlay, Display, TEXT("Jeu %s %s | moteur %s | configuration %s"),
		*Project->ProjectName, *Project->ProjectVersion,
		*FEngineVersion::Current().ToString(), LexToString(FApp::GetBuildConfiguration()));

	// Meme racine que ModdingExtra::LoadTxt : ProjectContentDir()/Modules
	const FString ModulesDir = FPaths::Combine(FPaths::ProjectContentDir(), TEXT("Modules"));
	IFileManager& FM = IFileManager::Get();
	if (!FM.DirectoryExists(*ModulesDir))
	{
		UE_LOG(LogLifePlay, Error, TEXT("Dossier de donnees absent : %s (verifier DirectoriesToAlwaysStageAsNonUFS)"),
			*FPaths::ConvertRelativePathToFull(ModulesDir));
		return;
	}

	TArray<FString> ModFiles;
	FM.FindFilesRecursive(ModFiles, *ModulesDir, TEXT("*.lpmod"), true, false);
	ModFiles.Sort();
	UE_LOG(LogLifePlay, Display, TEXT("Donnees : %s | %d module(s) | ModLauncher.config %s"),
		*FPaths::ConvertRelativePathToFull(ModulesDir), ModFiles.Num(),
		FM.FileExists(*FPaths::Combine(ModulesDir, TEXT("ModLauncher.config"))) ? TEXT("present") : TEXT("absent (tous les modules par defaut)"));

	for (const FString& ModFile : ModFiles)
	{
		const FString ModDir = FPaths::GetPath(ModFile);
		TArray<FString> Files;
		FM.FindFilesRecursive(Files, *ModDir, TEXT("*.*"), true, false);

		TMap<FString, int32> PerExt;
		for (const FString& F : Files) { ++PerExt.FindOrAdd(FPaths::GetExtension(F).ToLower()); }
		PerExt.ValueSort([](int32 A, int32 B) { return A > B; });

		FString Detail;
		for (const auto& It : PerExt) { Detail += FString::Printf(TEXT(" %s=%d"), *It.Key, It.Value); }
		UE_LOG(LogLifePlay, Display, TEXT("  %-22s %5d fichier(s) :%s"), *FPaths::GetBaseFilename(ModFile), Files.Num(), *Detail);
	}
}

void ULPSessionLogSubsystem::LogSessionSummary() const
{
	if (!Counter.IsValid())
	{
		return;
	}

	TArray<TPair<FString, int32>> Categories, Signatures;
	int32 Overflow = 0;
	Counter->Snapshot(Categories, Signatures, Overflow);

	const auto ByCountDesc = [](const TPair<FString, int32>& A, const TPair<FString, int32>& B) { return A.Value > B.Value; };
	Categories.Sort(ByCountDesc);
	Signatures.Sort(ByCountDesc);

	UE_LOG(LogLifePlay, Display, TEXT("===== LifePlay : bilan de session (%.0f s) ====="), FPlatformTime::Seconds() - StartTime);
	UE_LOG(LogLifePlay, Display, TEXT("Messages par categorie et verbosite (20 premieres) :"));
	for (int32 i = 0; i < FMath::Min(20, Categories.Num()); ++i)
	{
		UE_LOG(LogLifePlay, Display, TEXT("  %8d  %s"), Categories[i].Value, *Categories[i].Key);
	}

	UE_LOG(LogLifePlay, Display, TEXT("Avertissements et erreurs : %d signature(s) distincte(s)%s ; les %d plus frequentes :"),
		Signatures.Num(), Overflow ? *FString::Printf(TEXT(", %d message(s) hors plafond"), Overflow) : TEXT(""), TopSignatures);
	for (int32 i = 0; i < FMath::Min(TopSignatures, Signatures.Num()); ++i)
	{
		UE_LOG(LogLifePlay, Display, TEXT("  %8d  %s"), Signatures[i].Value, *Signatures[i].Key);
	}
}