// 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" 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>& OutCategories, TArray>& 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 PerCategory; TMap Signatures; int32 Overflow = 0; }; void ULPSessionLogSubsystem::Initialize(FSubsystemCollectionBase& Collection) { Super::Initialize(Collection); StartTime = FPlatformTime::Seconds(); Counter = MakeShared(); 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(); } 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(Prop)) { TypeName = SP->Struct->GetName(); } if (const FArrayProperty* AP = CastField(Prop)) { if (const FStructProperty* ISP = CastField(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& Keywords) { if (!Frame.Node || !Frame.Locals) { return; } int32 Shown = 0; for (TFieldIterator 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(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 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 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 GIVars; GIVarsList.ParseIntoArray(GIVars, TEXT(","), true); const TWeakObjectPtr 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 Count = MakeShared(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(""); if (Prop) { Value.Reset(); Prop->ExportTextItem_Direct(Value, Prop->ContainerPtrToValuePtr(GI), nullptr, const_cast(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 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(Prop)) { FScriptArrayHelper Helper(ArrayProp, ArrayProp->ContainerPtrToValuePtr(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(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(GI), nullptr, const_cast(GI), PPF_None); UE_LOG(LogLifePlay, Display, TEXT("[dump %s] %s = %s"), When, *Name, *Text.Left(600)); } } } void ULPSessionLogSubsystem::Deinitialize() { 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(); 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 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 Files; FM.FindFilesRecursive(Files, *ModDir, TEXT("*.*"), true, false); TMap 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> Categories, Signatures; int32 Overflow = 0; Counter->Snapshot(Categories, Signatures, Overflow); const auto ByCountDesc = [](const TPair& A, const TPair& 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); } }