diff --git a/src/SharpEmu.Core/Cpu/Native/DirectExecutionBackend.Diagnostics.cs b/src/SharpEmu.Core/Cpu/Native/DirectExecutionBackend.Diagnostics.cs index e39b4c5..b279054 100644 --- a/src/SharpEmu.Core/Cpu/Native/DirectExecutionBackend.Diagnostics.cs +++ b/src/SharpEmu.Core/Cpu/Native/DirectExecutionBackend.Diagnostics.cs @@ -8,6 +8,7 @@ using System.Linq; using System.Runtime.InteropServices; using System.Threading; using SharpEmu.HLE; +using SharpEmu.Logging; namespace SharpEmu.Core.Cpu.Native; @@ -43,7 +44,7 @@ public sealed partial class DirectExecutionBackend { return; } - Console.Error.WriteLine($"[LOADER][INFO] Recent import calls ({_recentImportTraceCount}):"); + Log.Info($" Recent import calls ({_recentImportTraceCount}):"); int num = (_recentImportTraceWriteIndex - _recentImportTraceCount + _recentImportTrace.Length) % _recentImportTrace.Length; for (int i = 0; i < _recentImportTraceCount; i++) { @@ -51,8 +52,8 @@ public sealed partial class DirectExecutionBackend var entry = _recentImportTrace[num2]; if (!string.IsNullOrEmpty(entry.Nid)) { - Console.Error.WriteLine( - $"[LOADER][INFO] #{entry.DispatchIndex} nid={entry.Nid} ret=0x{entry.ReturnRip:X16} " + + Log.Info( + $" #{entry.DispatchIndex} nid={entry.Nid} ret=0x{entry.ReturnRip:X16} " + $"rdi=0x{entry.Arg0:X16} rsi=0x{entry.Arg1:X16} rdx=0x{entry.Arg2:X16}"); } } @@ -91,12 +92,12 @@ public sealed partial class DirectExecutionBackend list.Add(num7); if (num2 < 32) { - Console.Error.WriteLine($"[LOADER][INFO] Suspicious unresolved pointer: slot=0x{num7:X16} value=0x{value2:X16}"); + Log.Info($"Suspicious unresolved pointer: slot=0x{num7:X16} value=0x{value2:X16}"); num2++; } if (num >= 16384) { - Console.Error.WriteLine($"[LOADER][WARNING] Suspicious unresolved pointer scan reached cap ({16384}); truncating."); + Log.Warning($"Suspicious unresolved pointer scan reached cap ({16384}); truncating."); return list; } } @@ -106,7 +107,7 @@ public sealed partial class DirectExecutionBackend } if (num != 0) { - Console.Error.WriteLine($"[LOADER][WARNING] Suspicious unresolved pointer hits: {num}"); + Log.Warning($"Suspicious unresolved pointer hits: {num}"); } return list; } @@ -121,18 +122,18 @@ public sealed partial class DirectExecutionBackend Span destination = stackalloc byte[128]; if (!cpuContext.Memory.TryRead(returnRip, destination)) { - Console.Error.WriteLine($"[LOADER][TRACE] Import#{dispatchIndex} return-rip probe: unreadable @0x{returnRip:X16}"); + Log.Debug($"Import#{dispatchIndex} return-rip probe: unreadable @0x{returnRip:X16}"); return; } string value = BitConverter.ToString(destination.ToArray()).Replace("-", " "); - Console.Error.WriteLine($"[LOADER][TRACE] Import#{dispatchIndex} return-rip bytes @0x{returnRip:X16}: {value}"); + Log.Debug($"Import#{dispatchIndex} return-rip bytes @0x{returnRip:X16}: {value}"); if (destination[0] == byte.MaxValue && (destination[1] == 21 || destination[1] == 37)) { int num = BitConverter.ToInt32(destination.Slice(2, 4)); ulong num2 = returnRip + 6 + (ulong)num; if (cpuContext.TryReadUInt64(num2, out var value2)) { - Console.Error.WriteLine($"[LOADER][TRACE] Import#{dispatchIndex} return-rip slot: [0x{num2:X16}] = 0x{value2:X16}"); + Log.Debug($"Import#{dispatchIndex} return-rip slot: [0x{num2:X16}] = 0x{value2:X16}"); } } if (destination[0] == 72 && destination[1] == 139 && destination[2] == 5) @@ -141,7 +142,7 @@ public sealed partial class DirectExecutionBackend ulong num4 = returnRip + 7 + (ulong)num3; if (cpuContext.TryReadUInt64(num4, out var value3)) { - Console.Error.WriteLine($"[LOADER][TRACE] Import#{dispatchIndex} return-rip mov-slot: [0x{num4:X16}] = 0x{value3:X16}"); + Log.Debug($"Import#{dispatchIndex} return-rip mov-slot: [0x{num4:X16}] = 0x{value3:X16}"); } } for (int i = 0; i + 6 <= destination.Length; i++) @@ -153,7 +154,7 @@ public sealed partial class DirectExecutionBackend ulong num7 = num6 + 6 + (ulong)num5; if (cpuContext.TryReadUInt64(num7, out var value4)) { - Console.Error.WriteLine($"[LOADER][TRACE] Import#{dispatchIndex} near-indirect @{num6:X16}: slot=0x{num7:X16} val=0x{value4:X16}"); + Log.Debug($"Import#{dispatchIndex} near-indirect @{num6:X16}: slot=0x{num7:X16} val=0x{value4:X16}"); } } } @@ -168,7 +169,7 @@ public sealed partial class DirectExecutionBackend int rel32 = BitConverter.ToInt32(destination.Slice(i + 1, 4)); ulong callRip = returnRip + (ulong)i; ulong target = unchecked((ulong)((long)(callRip + 5) + rel32)); - Console.Error.WriteLine($"[LOADER][TRACE] Import#{dispatchIndex} near-call @{callRip:X16}: target=0x{target:X16}"); + Log.Debug($"Import#{dispatchIndex} near-call @{callRip:X16}: target=0x{target:X16}"); for (int importIndex = 0; importIndex < _importEntries.Length; importIndex++) { if (_importEntries[importIndex].Address != target) @@ -179,21 +180,21 @@ public sealed partial class DirectExecutionBackend string nid = _importEntries[importIndex].Nid; if (_moduleManager.TryGetExport(nid, out var export)) { - Console.Error.WriteLine( - $"[LOADER][TRACE] Import#{dispatchIndex} near-call import: index={importIndex} {export.LibraryName}:{export.Name} ({nid})"); + Log.Debug( + $"Import#{dispatchIndex} near-call import: index={importIndex} {export.LibraryName}:{export.Name} ({nid})"); } else { - Console.Error.WriteLine( - $"[LOADER][TRACE] Import#{dispatchIndex} near-call import: index={importIndex} nid={nid}"); + Log.Debug( + $"Import#{dispatchIndex} near-call import: index={importIndex} nid={nid}"); } break; } if (cpuContext.Memory.TryRead(target, targetBytes)) { - Console.Error.WriteLine( - $"[LOADER][TRACE] Import#{dispatchIndex} near-call target bytes @0x{target:X16}: " + + Log.Debug( + $"Import#{dispatchIndex} near-call target bytes @0x{target:X16}: " + BitConverter.ToString(targetBytes.ToArray()).Replace("-", " ")); if (targetBytes[0] == 0xFF && targetBytes[1] == 0x25) { @@ -201,8 +202,8 @@ public sealed partial class DirectExecutionBackend ulong slot = unchecked((ulong)((long)(target + 6) + slotRel32)); if (cpuContext.TryReadUInt64(slot, out var slotTarget)) { - Console.Error.WriteLine( - $"[LOADER][TRACE] Import#{dispatchIndex} near-call PLT slot: [0x{slot:X16}] = 0x{slotTarget:X16}"); + Log.Debug( + $"Import#{dispatchIndex} near-call PLT slot: [0x{slot:X16}] = 0x{slotTarget:X16}"); for (int importIndex = 0; importIndex < _importEntries.Length; importIndex++) { if (_importEntries[importIndex].Address != slotTarget) @@ -213,13 +214,13 @@ public sealed partial class DirectExecutionBackend string nid = _importEntries[importIndex].Nid; if (_moduleManager.TryGetExport(nid, out var export)) { - Console.Error.WriteLine( - $"[LOADER][TRACE] Import#{dispatchIndex} near-call PLT import: index={importIndex} {export.LibraryName}:{export.Name} ({nid})"); + Log.Debug( + $"Import#{dispatchIndex} near-call PLT import: index={importIndex} {export.LibraryName}:{export.Name} ({nid})"); } else { - Console.Error.WriteLine( - $"[LOADER][TRACE] Import#{dispatchIndex} near-call PLT import: index={importIndex} nid={nid}"); + Log.Debug( + $"Import#{dispatchIndex} near-call PLT import: index={importIndex} nid={nid}"); } break; } diff --git a/src/SharpEmu.Core/Cpu/Native/DirectExecutionBackend.cs b/src/SharpEmu.Core/Cpu/Native/DirectExecutionBackend.cs index 1c06fa8..c17bb7b 100644 --- a/src/SharpEmu.Core/Cpu/Native/DirectExecutionBackend.cs +++ b/src/SharpEmu.Core/Cpu/Native/DirectExecutionBackend.cs @@ -11,11 +11,13 @@ using SharpEmu.Core.Cpu; using SharpEmu.Core.Loader; using SharpEmu.Core.Memory; using SharpEmu.HLE; +using SharpEmu.Logging; namespace SharpEmu.Core.Cpu.Native; public sealed unsafe partial class DirectExecutionBackend : INativeCpuBackend, IGuestThreadScheduler, IDisposable { + private static readonly SharpEmuLogger Log = SharpEmuLog.For("Native"); private const int ImportLoopHistoryLength = 2048; private const int ImportLoopWideDiversityWindow = 768; diff --git a/src/SharpEmu.Core/Loader/SelfLoader.cs b/src/SharpEmu.Core/Loader/SelfLoader.cs index 76dc042..84299a9 100644 --- a/src/SharpEmu.Core/Loader/SelfLoader.cs +++ b/src/SharpEmu.Core/Loader/SelfLoader.cs @@ -10,11 +10,13 @@ using SharpEmu.Core; using SharpEmu.Core.Cpu; using SharpEmu.Core.Memory; using SharpEmu.HLE; +using SharpEmu.Logging; namespace SharpEmu.Core.Loader; public sealed class SelfLoader : ISelfLoader { + private static readonly SharpEmuLogger Log = SharpEmuLog.For("Loader"); private const uint SelfMagic = 0x4F153D1D; private const ulong SelfSegmentFlag = 0x800; private const int PageSize = 0x1000; @@ -155,7 +157,7 @@ public sealed class SelfLoader : ISelfLoader } var tlsModuleId = _nextTlsModuleId == 0 ? 1u : _nextTlsModuleId; - Console.Error.WriteLine($"[LOADER][TLS] load_start clear={clearVirtualMemory} next={_nextTlsModuleId} assigned={tlsModuleId}"); + Log.Debug($"TLS load_start clear={clearVirtualMemory} next={_nextTlsModuleId} assigned={tlsModuleId}"); var loadContext = ParseLayout(imageData); var elfHeader = ReadUnmanaged(imageData, loadContext.ElfOffset); @@ -255,7 +257,7 @@ public sealed class SelfLoader : ISelfLoader { _nextTlsModuleId++; } - Console.Error.WriteLine($"[LOADER][TLS] load_done assigned={tlsModuleId} next={_nextTlsModuleId}"); + Log.Debug($"TLS load_done assigned={tlsModuleId} next={_nextTlsModuleId}"); return new SelfImage( loadContext.IsSelf, @@ -403,15 +405,15 @@ public sealed class SelfLoader : ISelfLoader var virtualAddress = header.VirtualAddress + imageBase; - Console.Error.WriteLine($"[LOADER] Segment {index}: VAddr=0x{virtualAddress:X16}, FileSize=0x{header.FileSize:X}, MemSize=0x{header.MemorySize:X}, Align=0x{header.Alignment:X}"); + Log.Debug($"Segment {index}: VAddr=0x{virtualAddress:X16}, FileSize=0x{header.FileSize:X}, MemSize=0x{header.MemorySize:X}, Align=0x{header.Alignment:X}"); if (header.Alignment > 1) { var vaddrMod = virtualAddress % header.Alignment; var offsetMod = header.Offset % header.Alignment; if (vaddrMod != offsetMod) { - Console.Error.WriteLine( - $"[LOADER] WARNING: Segment {index} ELF alignment mismatch! " + + Log.Warning( + $"Segment {index} ELF alignment mismatch! " + $"VAddr=0x{virtualAddress:X}, Offset=0x{header.Offset:X}, Align=0x{header.Alignment:X}, " + $"VAddr%Align=0x{vaddrMod:X}, Offset%Align=0x{offsetMod:X}"); } @@ -671,13 +673,13 @@ public sealed class SelfLoader : ISelfLoader { if (descriptor.ValueKind == RelocationValueKind.TlsModuleId) { - Console.Error.WriteLine( - $"[LOADER][TLS] Patching DTPMOD64 at 0x{descriptor.TargetAddress:X} with module id 0x{targetValue:X}"); + Log.Debug( + $"Patching DTPMOD64 at 0x{descriptor.TargetAddress:X} with module id 0x{targetValue:X}"); } else { - Console.Error.WriteLine($"[LOADER] !!! CRITICAL !!! Patching address 0x{descriptor.TargetAddress:X} with INVALID value 0x{targetValue:X} for NID {descriptor.ImportNid ?? "(null)"}"); - Console.Error.WriteLine($"[LOADER] SymbolValue=0x{descriptor.SymbolValue:X}, Addend=0x{descriptor.Addend:X}, StubAddress=0x{(addressesByNid.TryGetValue(descriptor.ImportNid ?? "", out var sa) ? sa : 0):X}"); + Log.Warning($"!!! CRITICAL !!! Patching address 0x{descriptor.TargetAddress:X} with INVALID value 0x{targetValue:X} for NID {descriptor.ImportNid ?? "(null)"}"); + Log.Warning($" SymbolValue=0x{descriptor.SymbolValue:X}, Addend=0x{descriptor.Addend:X}, StubAddress=0x{(addressesByNid.TryGetValue(descriptor.ImportNid ?? "", out var sa) ? sa : 0):X}"); } } @@ -689,8 +691,8 @@ public sealed class SelfLoader : ISelfLoader if (descriptor.TargetAddress >= 0x00000008030FC300UL && descriptor.TargetAddress <= 0x00000008030FC3F0UL) { - Console.Error.WriteLine( - $"[LOADER][RELOC] target=0x{descriptor.TargetAddress:X16} value=0x{targetValue:X16} addend=0x{descriptor.Addend:X} nid={(descriptor.ImportNid ?? "")}"); + Log.Debug( + $"[RELOC] target=0x{descriptor.TargetAddress:X16} value=0x{targetValue:X16} addend=0x{descriptor.Addend:X} nid={(descriptor.ImportNid ?? "")}"); } } @@ -783,15 +785,15 @@ public sealed class SelfLoader : ISelfLoader { if (IsFocusRelocationOffset(relocation.Offset, imageBase)) { - Console.Error.WriteLine( - $"[LOADER][FOCUS][SCAN] off=0x{relocation.Offset:X16} type={relocation.Type} sym={relocation.SymbolIndex} addend=0x{relocation.Addend:X}"); + Log.Debug( + $"[FOCUS][SCAN] off=0x{relocation.Offset:X16} type={relocation.Type} sym={relocation.SymbolIndex} addend=0x{relocation.Addend:X}"); } if (!IsSupportedRelocationType(relocation.Type)) { if (IsFocusRelocationOffset(relocation.Offset, imageBase)) { - Console.Error.WriteLine($"[LOADER][FOCUS][SKIP] unsupported type={relocation.Type}"); + Log.Debug($"[FOCUS][SKIP] unsupported type={relocation.Type}"); } continue; } @@ -800,7 +802,7 @@ public sealed class SelfLoader : ISelfLoader { if (IsFocusRelocationOffset(relocation.Offset, imageBase)) { - Console.Error.WriteLine("[LOADER][FOCUS][SKIP] target address not mapped"); + Log.Debug("[FOCUS][SKIP] target address not mapped"); } continue; } @@ -840,7 +842,7 @@ public sealed class SelfLoader : ISelfLoader { if (targetAddress >= FocusRelocGuestStart && targetAddress <= FocusRelocGuestEnd) { - Console.Error.WriteLine($"[LOADER][FOCUS][SKIP] symbol read failed index={symbolIndex}"); + Log.Debug($"[FOCUS][SKIP] symbol read failed index={symbolIndex}"); } continue; } @@ -852,10 +854,9 @@ public sealed class SelfLoader : ISelfLoader var symbolAddress = ResolveMappedAddressOrFallback(virtualMemory, symbol.Value, imageBase); if (symbolAddress == 0) { - Console.Error.WriteLine( - $"[LOADER] Skipping local relocation with invalid symbol value 0x{symbol.Value:X} " + + Log.Warning( + $"Skipping local relocation with invalid symbol value 0x{symbol.Value:X} " + $"at target 0x{targetAddress:X16}, type={relocation.Type}, sym={symbolIndex}"); - continue; } descriptors.Add(new RelocationDescriptor( @@ -873,10 +874,9 @@ public sealed class SelfLoader : ISelfLoader var symbolAddress = ResolveMappedAddressOrFallback(virtualMemory, symbol.Value, imageBase); if (symbolAddress == 0) { - Console.Error.WriteLine( - $"[LOADER] Skipping relocation with invalid symbol value 0x{symbol.Value:X} " + + Log.Warning( + $"Skipping relocation with invalid symbol value 0x{symbol.Value:X} " + $"at target 0x{targetAddress:X16}, type={relocation.Type}, sym={symbolIndex}"); - continue; } descriptors.Add(new RelocationDescriptor( @@ -893,7 +893,7 @@ public sealed class SelfLoader : ISelfLoader { if (targetAddress >= FocusRelocGuestStart && targetAddress <= FocusRelocGuestEnd) { - Console.Error.WriteLine($"[LOADER][FOCUS][SKIP] bind={symbolBind} not importable"); + Log.Debug($"[FOCUS][SKIP] bind={symbolBind} not importable"); } continue; } @@ -902,7 +902,7 @@ public sealed class SelfLoader : ISelfLoader { if (targetAddress >= FocusRelocGuestStart && targetAddress <= FocusRelocGuestEnd) { - Console.Error.WriteLine($"[LOADER][FOCUS][SKIP] symbol name read failed offset={symbol.NameOffset}"); + Log.Debug($"[FOCUS][SKIP] symbol name read failed offset={symbol.NameOffset}"); } continue; } @@ -950,8 +950,8 @@ public sealed class SelfLoader : ISelfLoader if (sectionSymbols > 0 || dynamicSymbols > 0) { - Console.Error.WriteLine( - $"[LOADER] Runtime symbol index populated: section={sectionSymbols}, dynamic={dynamicSymbols}, total={runtimeSymbols.Count}"); + Log.Info( + $"Runtime symbol index populated: section={sectionSymbols}, dynamic={dynamicSymbols}, total={runtimeSymbols.Count}"); } } @@ -1025,8 +1025,8 @@ public sealed class SelfLoader : ISelfLoader if (preInitializers.Count != 0 || initializers.Count != 0) { - Console.Error.WriteLine( - $"[LOADER] Initializers discovered: preinit={preInitializers.Count}, init={initializers.Count}"); + Log.Info( + $"Initializers discovered: preinit={preInitializers.Count}, init={initializers.Count}"); } } @@ -1409,8 +1409,8 @@ public sealed class SelfLoader : ISelfLoader var requiredBytes = checked((ulong)orderedImportNids.Count * ImportStubSlotSize); var mapSize = AlignUp(Math.Max(requiredBytes, (ulong)PageSize), PageSize); - Console.Error.WriteLine( - $"[LOADER] CreateImportStubMapping: nids={orderedImportNids.Count}, required=0x{requiredBytes:X}, map_size=0x{mapSize:X}"); + Log.Debug( + $"CreateImportStubMapping: nids={orderedImportNids.Count}, required=0x{requiredBytes:X}, map_size=0x{mapSize:X}"); if (mapSize > int.MaxValue) { throw new NotSupportedException("Import stub mapping exceeds 2 GB and is not supported."); @@ -1842,16 +1842,16 @@ public sealed class SelfLoader : ISelfLoader tableBytes = GC.AllocateUninitializedArray((int)size); var guestAddr = location + imageBase; - Console.Error.WriteLine($"[LOADER] TryLoadTableBytes: trying guest address 0x{guestAddr:X}"); + Log.Debug($"TryLoadTableBytes: trying guest address 0x{guestAddr:X}"); if (virtualMemory.TryRead(guestAddr, tableBytes)) { - Console.Error.WriteLine($"[LOADER] TryLoadTableBytes: loaded from guest memory at 0x{guestAddr:X}"); + Log.Debug($"TryLoadTableBytes: loaded from guest memory at 0x{guestAddr:X}"); return true; } if (virtualMemory.TryRead(location, tableBytes)) { - Console.Error.WriteLine($"[LOADER] TryLoadTableBytes: loaded from absolute guest address 0x{location:X}"); + Log.Debug($"TryLoadTableBytes: loaded from absolute guest address 0x{location:X}"); return true; } @@ -1859,11 +1859,11 @@ public sealed class SelfLoader : ISelfLoader { var slice = elfData.Slice((int)location, (int)size); tableBytes = slice.ToArray(); - Console.Error.WriteLine($"[LOADER] TryLoadTableBytes: loaded from elfData as file offset at 0x{location:X}"); + Log.Debug($"TryLoadTableBytes: loaded from elfData as file offset at 0x{location:X}"); return true; } - Console.Error.WriteLine($"[LOADER] TryLoadTableBytes: FAILED for location 0x{location:X}"); + Log.Warning($"TryLoadTableBytes: FAILED for location 0x{location:X}"); tableBytes = Array.Empty(); return false; } @@ -1920,17 +1920,17 @@ public sealed class SelfLoader : ISelfLoader private static ulong ResolveMappedAddressOrFallback(IVirtualMemory virtualMemory, ulong address, ulong imageBase) { - Console.Error.WriteLine($"[LOADER][TEST] ResolveMappedAddressOrFallback addr=0x{address:X} imageBase=0x{imageBase:X16}"); + Log.Debug($"ResolveMappedAddressOrFallback addr=0x{address:X} imageBase=0x{imageBase:X16}"); if (address == 0) { - Console.Error.WriteLine("[LOADER][TEST] -> return 0 (null)"); + Log.Debug("-> return 0 (null)"); return 0; } if (TryResolveMappedAddress(virtualMemory, address, imageBase, 1, out var resolved)) { - Console.Error.WriteLine($"[LOADER][TEST] -> resolved raw 0x{resolved:X16}"); + Log.Debug($"-> resolved raw 0x{resolved:X16}"); return resolved; } @@ -1939,18 +1939,18 @@ public sealed class SelfLoader : ISelfLoader var rebased = address + imageBase; if (TryResolveMappedAddress(virtualMemory, rebased, imageBase, 1, out var resolvedRebased)) { - Console.Error.WriteLine($"[LOADER][TEST] -> resolved rebased 0x{resolvedRebased:X16}"); + Log.Debug($"-> resolved rebased 0x{resolvedRebased:X16}"); return resolvedRebased; } } if (address < 0x10000) { - Console.Error.WriteLine($"[LOADER][TEST] -> reject small 0x{address:X}"); + Log.Debug($"-> reject small 0x{address:X}"); return 0; } - Console.Error.WriteLine($"[LOADER][TEST] -> fallback raw 0x{address:X}"); + Log.Debug($"-> fallback raw 0x{address:X}"); return address; }