Skip to content

Commit

Permalink
[General] logging improvements
Browse files Browse the repository at this point in the history
  • Loading branch information
Chris Weermann (TGE) committed Jul 10, 2020
1 parent 7808677 commit f4b7584
Show file tree
Hide file tree
Showing 12 changed files with 189 additions and 102 deletions.
70 changes: 70 additions & 0 deletions modloader/FileLoggingLogger.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,70 @@
using Reloaded.Mod.Interfaces;
using System;
using System.Drawing;
using System.IO;

namespace modloader
{
public class FileLoggingLogger : ILogger
{
private readonly ILogger mLogger;
private StreamWriter mWriter;

public FileLoggingLogger( ILogger logger, string filePath )
{
mLogger = logger;
mWriter = File.CreateText( filePath );
}

public Color BackgroundColor { get => mLogger.BackgroundColor; set => mLogger.BackgroundColor = value; }
public Color TextColor { get => mLogger.TextColor; set => mLogger.TextColor = value; }
public Color ColorRed { get => mLogger.ColorRed; set => mLogger.ColorRed = value; }
public Color ColorRedLight { get => mLogger.ColorRedLight; set => mLogger.ColorRedLight = value; }
public Color ColorGreen { get => mLogger.ColorGreen; set => mLogger.ColorGreen = value; }
public Color ColorGreenLight { get => mLogger.ColorGreenLight; set => mLogger.ColorGreenLight = value; }
public Color ColorYellow { get => mLogger.ColorYellow; set => mLogger.ColorYellow = value; }
public Color ColorYellowLight { get => mLogger.ColorYellowLight; set => mLogger.ColorYellowLight = value; }
public Color ColorBlue { get => mLogger.ColorBlue; set => mLogger.ColorBlue = value; }
public Color ColorBlueLight { get => mLogger.ColorBlueLight; set => mLogger.ColorBlueLight = value; }
public Color ColorPink { get => mLogger.ColorPink; set => mLogger.ColorPink = value; }
public Color ColorPinkLight { get => mLogger.ColorPinkLight; set => mLogger.ColorPinkLight = value; }
public Color ColorLightBlue { get => mLogger.ColorLightBlue; set => mLogger.ColorLightBlue = value; }
public Color ColorLightBlueLight { get => mLogger.ColorLightBlueLight; set => mLogger.ColorLightBlueLight = value; }

public event EventHandler<string> OnPrintMessage
{
add
{
mLogger.OnPrintMessage += value;
}

remove
{
mLogger.OnPrintMessage -= value;
}
}

public void PrintMessage( string message, Color color )
=> mLogger.PrintMessage( message, color );

public void Write( string message )
=> mLogger.Write( message );

public void WriteLine( string message )
=> mLogger.WriteLine( message );

public void Write( string message, Color color )
{
mWriter.Write( message );
mWriter.Flush();
mLogger.Write( message, color );
}

public void WriteLine( string message, Color color )
{
mWriter.WriteLine( message );
mWriter.Flush();
mLogger.WriteLine( message, color );
}
}
}
2 changes: 1 addition & 1 deletion modloader/ModConfig.json
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@
"ModId": "p4gpc.modloader",
"ModName": "Persona 4 Golden PC Mod Loader",
"ModAuthor": "TGE, Sewer56",
"ModVersion": "1.1.2",
"ModVersion": "1.2.0",
"ModDescription": "A mod loader for Persona 4 Golden (Steam)",
"ModDll": "modloader.dll",
"ModIcon": "Preview.png",
Expand Down
12 changes: 9 additions & 3 deletions modloader/P4GPCModLoader.cs
Original file line number Diff line number Diff line change
Expand Up @@ -24,7 +24,13 @@ public unsafe class P4GPCModLoader

public P4GPCModLoader( ILogger logger, Config configuration, Reloaded.Hooks.ReloadedII.Interfaces.IReloadedHooks hooks )
{
mLogger = logger;
// Enable file logging only if console is enabled
// performance impact would be too great otherwise
if ( Native.GetConsoleWindow() != IntPtr.Zero )
mLogger = new FileLoggingLogger( logger, "p4gpc.modloader.log.txt" );
else
mLogger = logger;

mConfiguration = configuration;
mHooks = hooks;

Expand All @@ -42,11 +48,11 @@ public P4GPCModLoader( ILogger logger, Config configuration, Reloaded.Hooks.Relo
var modDb = new ModDb( mConfiguration.ModsDirectory, mConfiguration.EnabledMods );

// DW_PACK (PAC) redirector
mDwPackRedirector = new DwPackRedirector( logger, modDb );
mDwPackRedirector = new DwPackRedirector( mLogger, modDb );
mFileAccessServer.AddClient( mDwPackRedirector );

// XACT (XWB, XSB) redirector
mXactRedirector = new XactRedirector( logger, modDb );
mXactRedirector = new XactRedirector( mLogger, modDb );
mFileAccessServer.AddClient( mXactRedirector );
}

Expand Down
43 changes: 18 additions & 25 deletions modloader/Redirectors/DwPack/DwPackRedirector.cs
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,7 @@ namespace modloader.Redirectors.DwPack
public unsafe class DwPackRedirector : FileAccessClient
{
private static readonly Regex sPacFileNameRegex = new Regex(@".+\d{5}.pac", RegexOptions.Compiled | RegexOptions.IgnoreCase);
private readonly ILogger mLogger;
private readonly SemanticLogger mLogger;
private readonly ModDb mModDb;
private readonly Dictionary<IntPtr, VirtualDwPack> mPacksByHandle;
private readonly Dictionary<string, VirtualDwPack> mPacksByName;
Expand All @@ -26,7 +26,7 @@ public unsafe class DwPackRedirector : FileAccessClient

public DwPackRedirector( ILogger logger, ModDb modDb )
{
mLogger = logger;
mLogger = new SemanticLogger( logger, "[modloader:DwPackRedirector]" );
mModDb = modDb;
mPacksByHandle = new Dictionary<IntPtr, VirtualDwPack>();
mPacksByName = new Dictionary<string, VirtualDwPack>( StringComparer.OrdinalIgnoreCase );
Expand Down Expand Up @@ -70,13 +70,13 @@ public override Native.NtStatus NtCreateFileImpl( string filePath, out IntPtr ha
result = mHooks.NtCreateFileHook.OriginalFunction( out handle, access, ref objectAttributes, ref ioStatus, ref allocSize,
fileAttributes, share, createDisposition, createOptions, eaBuffer, eaLength );

Debug( $"Registered {filePath}" );
mLogger.Debug( $"Registered {filePath}" );

// Entries are redirected as needed to improve startup performance
}

mPacksByHandle[handle] = pack;
Debug( $"Hnd {handle} {filePath} handle registered" );
mLogger.Debug( $"Hnd {handle} {filePath} handle registered" );
return result;
}

Expand Down Expand Up @@ -104,24 +104,24 @@ private NtStatus ReadFile( IntPtr handle, IntPtr hEvent, IntPtr* apcRoutine, Int
// This is done as late as possible to improve startup times
if ( !entry.IsRedirected )
{
Info( $"{pack.FileName} Hnd: {handle} {entry.Native->Path} Data access Offset: 0x{effOffset:X8} Length: 0x{length:X8}" );
mLogger.Info( $"{pack.FileName} Hnd: {handle} {entry.Native->Path} Data access Offset: 0x{effOffset:X8} Length: 0x{length:X8}" );
result = mHooks.NtReadFileHook.OriginalFunction( handle, hEvent, apcRoutine, apcContext, ref ioStatus, buffer, length, byteOffset, key );
}
else
{
Info( $"{pack.FileName} Hnd: {handle} {entry.Native->Path} Data access Offset: 0x{effOffset:X8} Length: 0x{length:X8} redirected to {entry.RedirectedFilePath}" );
mLogger.Info( $"{pack.FileName} Hnd: {handle} {entry.Native->Path} Data access Offset: 0x{effOffset:X8} Length: 0x{length:X8} redirected to {entry.RedirectedFilePath}" );
result = NtStatus.Success;

if ( fileDataOffset < 0 )
{
Error( $"{pack.FileName} Hnd: {handle} {entry.Native->Path} Offset is before start of data!!!" );
mLogger.Error( $"{pack.FileName} Hnd: {handle} {entry.Native->Path} Offset is before start of data!!!" );
}
else if ( fileDataOffset > entry.RedirectedFileSize )
{
Error( $"{pack.FileName} Hnd: {handle} {entry.Native->Path} Offset is after end of data!!!" );
mLogger.Error( $"{pack.FileName} Hnd: {handle} {entry.Native->Path} Offset is after end of data!!!" );
}

Debug( $"{pack.FileName} Hnd: {handle} {entry.Native->Path} Reading 0x{length:X8} bytes from redirected file at offset 0x{fileDataOffset:X8}" );
mLogger.Debug( $"{pack.FileName} Hnd: {handle} {entry.Native->Path} Reading 0x{length:X8} bytes from redirected file at offset 0x{fileDataOffset:X8}" );

// Get cached file stream if the file was previously opened or open a new file
Stream redirectedStream;
Expand All @@ -144,21 +144,21 @@ private NtStatus ReadFile( IntPtr handle, IntPtr hEvent, IntPtr* apcRoutine, Int
SetBytesRead( handle, ( int )offset, ( int )length, ref ioStatus );

if ( readBytes != length )
Error( $"{pack.FileName} Hnd: {handle} {entry.Native->Path} File read length doesnt match requested read length!! Expected 0x{length:X8}, Actual 0x{readBytes:X8}" );
mLogger.Error( $"{pack.FileName} Hnd: {handle} {entry.Native->Path} File read length doesnt match requested read length!! Expected 0x{length:X8}, Actual 0x{readBytes:X8}" );

Debug( $"{pack.FileName} Hnd: {handle} {entry.Native->Path} Wrote redirected file to buffer" );
mLogger.Debug( $"{pack.FileName} Hnd: {handle} {entry.Native->Path} Wrote redirected file to buffer" );
}
catch ( Exception e )
{
Debug( $"{pack.FileName} Hnd: {handle} Index: {i} {entry.Native->Path} Unhandled exception thrown during reading {entry.RedirectedFilePath}: {e}" );
mLogger.Debug( $"{pack.FileName} Hnd: {handle} Index: {i} {entry.Native->Path} Unhandled exception thrown during reading {entry.RedirectedFilePath}: {e}" );
}
}

// Return early, we're done here
return result;
}

Error( $"{pack.FileName} Hnd: {handle} Unhandled file data read request!! Offset: 0x{effOffset:X8} Length: 0x{length:X8}" );
mLogger.Error( $"{pack.FileName} Hnd: {handle} Unhandled file data read request!! Offset: 0x{effOffset:X8} Length: 0x{length:X8}" );
return mHooks.NtReadFileHook.OriginalFunction( handle, hEvent, apcRoutine, apcContext, ref ioStatus, buffer, length, byteOffset, key );
}

Expand Down Expand Up @@ -207,12 +207,12 @@ public override unsafe Native.NtStatus NtReadFileImpl( IntPtr handle, IntPtr hEv
}
else
{
Error( $"{pack.FileName} Hnd: {handle} Unexpected read request!! Offset: {effOffset:X8} Length: {length:X8}" );
mLogger.Error( $"{pack.FileName} Hnd: {handle} Unexpected read request!! Offset: {effOffset:X8} Length: {length:X8}" );
result = mHooks.NtReadFileHook.OriginalFunction( handle, hEvent, apcRoutine, apcContext, ref ioStatus, buffer, length, byteOffset, key );
}

if ( result != NtStatus.Success )
Error( $"{pack.FileName} Hnd: {handle} NtReadFile failed with {result}!!!" );
mLogger.Error( $"{pack.FileName} Hnd: {handle} NtReadFile failed with {result}!!!" );

return result;
}
Expand All @@ -225,11 +225,11 @@ public override unsafe NtStatus NtSetInformationFileImpl( IntPtr hfile, out IO_S
{
var pack = mPacksByHandle[hfile];
pack.FilePointer = *( long* )fileInformation;
Debug( $"{pack.FileName} Hnd: {hfile} SetFilePointer -> 0x{pack.FilePointer:X8}" );
mLogger.Debug( $"{pack.FileName} Hnd: {hfile} SetFilePointer -> 0x{pack.FilePointer:X8}" );
}
else
{
Warning( $"SetInformationFileImpl(hfile = {hfile}, out ioStatusBlock, fileInformation = *0x{( long )fileInformation:X8}, " +
mLogger.Warning( $"SetInformationFileImpl(hfile = {hfile}, out ioStatusBlock, fileInformation = *0x{( long )fileInformation:X8}, " +
$"length = {length}, fileInformationClass = {fileInformationClass}" );
}

Expand All @@ -253,17 +253,10 @@ public override unsafe NtStatus NtQueryInformationFileImpl( IntPtr hfile, out Na
}
else
{
Debug( $"NtQueryInformationFileImpl( IntPtr hfile = {hfile}, out Native.IO_STATUS_BLOCK ioStatusBlock, void* fileInformation, length = {length}, fileInformationClass = {fileInformationClass} )" );
mLogger.Debug( $"NtQueryInformationFileImpl( IntPtr hfile = {hfile}, out Native.IO_STATUS_BLOCK ioStatusBlock, void* fileInformation, length = {length}, fileInformationClass = {fileInformationClass} )" );
}

return result;
}

private void Info( string msg ) => mLogger?.WriteLine( $"[modloader:DwPackRedirector] I {msg}" );
private void Warning( string msg ) => mLogger?.WriteLine( $"[modloader:DwPackRedirector] W {msg}", mLogger.ColorYellow );
private void Error( string msg ) => mLogger?.WriteLine( $"[modloader:DwPackRedirector] E {msg}", mLogger.ColorRed );

[Conditional( "DEBUG" )]
private void Debug( string msg ) => mLogger?.WriteLine( $"[modloader:DwPackRedirector] D {msg}", mLogger.ColorGreen );
}
}
17 changes: 4 additions & 13 deletions modloader/Redirectors/DwPack/VirtualDwPack.cs
Original file line number Diff line number Diff line change
Expand Up @@ -16,7 +16,7 @@ public unsafe class VirtualDwPack
{
public const long MAX_FILE_SIZE = uint.MaxValue;

private readonly ILogger mLogger;
private readonly SemanticLogger mLogger;
private MemoryMapper mMapper;

public DwPackPtr Native { get; private set; }
Expand All @@ -28,7 +28,7 @@ public unsafe class VirtualDwPack
public long DataBaseOffset => Native.Data - Native.Ptr;
public List<VirtualDwPackEntry> Entries { get; }

public VirtualDwPack( ILogger logger )
public VirtualDwPack( SemanticLogger logger )
{
mLogger = logger;
mMapper = new MemoryMapper();
Expand Down Expand Up @@ -70,20 +70,11 @@ public long ReallocateFileData( int dataOffset, int length )
var oldVirtualFileSize = VirtualFileSize;
VirtualFileSize = Math.Max( VirtualFileSize, offset + length );
if ( VirtualFileSize > MAX_FILE_SIZE )
mLogger.WriteLine( "[modloader:DwPackRedirector] E: Out of available memory! 4GB address space exhausted", mLogger.ColorRed );
mLogger.Error( "Out of available memory! 4GB address space exhausted" );
else if ( VirtualFileSize > oldVirtualFileSize )
mLogger.WriteLine( $"[modloader:DwPackRedirector] I: {FileName} Virtual size increased to 0x{VirtualFileSize:X8}" );
mLogger.Info( $"{FileName} Virtual size increased to 0x{VirtualFileSize:X8}" );

return ( long )( offset - DataBaseOffset );

//var offset = VirtualFileSize;
//VirtualFileSize += length;
//if ( VirtualFileSize > MAX_FILE_SIZE )
// mLogger.WriteLine( "[modloader:DwPackRedirector] E: Out of available memory! 4GB address space exhausted", mLogger.ColorRed );
//else
// mLogger.WriteLine( $"[modloader:DwPackRedirector] D: Virtual size increased to 0x{VirtualFileSize:X8}" );

//return ( long )( offset - ( Native.Data - Native.Ptr ) );
}
}
}
10 changes: 4 additions & 6 deletions modloader/Redirectors/DwPack/VirtualDwPackEntry.cs
Original file line number Diff line number Diff line change
Expand Up @@ -11,7 +11,7 @@ namespace modloader.Redirectors.DwPack
{
public unsafe class VirtualDwPackEntry
{
private readonly ILogger mLogger;
private readonly SemanticLogger mLogger;

public VirtualDwPack Pack { get; private set; }
public DwPackEntry* Native { get; private set; }
Expand All @@ -23,7 +23,7 @@ public unsafe class VirtualDwPackEntry
public string RedirectedFileName { get; private set; }
public long RedirectedFileSize { get; private set; }

public VirtualDwPackEntry( ILogger logger, VirtualDwPack pack, DwPackEntry* entry, int index )
public VirtualDwPackEntry( SemanticLogger logger, VirtualDwPack pack, DwPackEntry* entry, int index )
{
mLogger = logger;
Pack = pack;
Expand All @@ -47,14 +47,12 @@ public bool TryRedirect( ModDb modDb )
if ( mod.Files.Contains( redirectedFilePath ) )
{
Redirect( redirectedFilePath );
mLogger.WriteLine( $"[modloader:DwPackRedirector] I: {Pack.FileName} {Native->Path} Redirected to {redirectedFilePath}" );
mLogger.Info( $"{Pack.FileName} {Native->Path} Redirected to {redirectedFilePath}" );
return true;
}
else
{
#if DEBUG
mLogger.WriteLine( $"[modloader:DwPackRedirector] D: No redirection for {Native->Path} because {redirectedFilePath} does not exist." );
#endif
mLogger.Debug( $"No redirection for {Native->Path} because {redirectedFilePath} does not exist." );
}
}

Expand Down
4 changes: 2 additions & 2 deletions modloader/Redirectors/Xact/VirtualSoundBank.cs
Original file line number Diff line number Diff line change
Expand Up @@ -11,12 +11,12 @@ namespace modloader.Redirectors.Xact
{
public unsafe class VirtualSoundBank : IDisposable
{
private readonly ILogger mLogger;
private readonly SemanticLogger mLogger;
private readonly Dictionary<int, string> mTrackIndexToCueName;

public SoundBankPtr Native { get; private set; }

public VirtualSoundBank( ILogger logger )
public VirtualSoundBank( SemanticLogger logger )
{
mLogger = logger;
mTrackIndexToCueName = new Dictionary<int, string>();
Expand Down
6 changes: 3 additions & 3 deletions modloader/Redirectors/Xact/VirtualWaveBank.cs
Original file line number Diff line number Diff line change
Expand Up @@ -12,7 +12,7 @@ namespace modloader.Redirectors.Xact
{
internal unsafe class VirtualWaveBank
{
private readonly ILogger mLogger;
private readonly SemanticLogger mLogger;

public const long MAX_FILE_SIZE = uint.MaxValue;

Expand All @@ -24,7 +24,7 @@ internal unsafe class VirtualWaveBank
public long VirtualFileSize { get; private set; }
public List<VirtualWaveBankEntry> Entries { get; }

public VirtualWaveBank( ILogger logger )
public VirtualWaveBank( SemanticLogger logger )
{
mLogger = logger;
Entries = new List<VirtualWaveBankEntry>();
Expand Down Expand Up @@ -71,7 +71,7 @@ public long AllocateSectionMemory( WaveBankSegmentIndex segmentIndex, int length

var segmentOffset = offset - segment->Offset;
if ( segmentOffset > uint.MaxValue )
mLogger.WriteLine( "[modloader:XactRedirector] E: Out of available memory! 4GB address space exhausted", mLogger.ColorRed );
mLogger.Error( "Out of available memory! 4GB address space exhausted" );

segment->Length += ( int )( VirtualFileSize - origVirtualSize );
return segmentOffset;
Expand Down
Loading

0 comments on commit f4b7584

Please sign in to comment.