362 lines
15 KiB
C#
362 lines
15 KiB
C#
using System.Text;
|
||
using System.Text.Json;
|
||
|
||
namespace Ananta.SDK.Logging;
|
||
|
||
/// <summary>
|
||
/// Process-wide runtime logs shared by the SDK and server.
|
||
/// Run-All.ps1 supplies one run id so C# and the Node proxy append to the same console files.
|
||
/// </summary>
|
||
public static class RuntimeLogs
|
||
{
|
||
private static readonly object FileLock = new();
|
||
private static readonly JsonSerializerOptions JsonOptions = new()
|
||
{
|
||
IncludeFields = true,
|
||
WriteIndented = false,
|
||
MaxDepth = 8,
|
||
};
|
||
|
||
private static bool _initialized;
|
||
private static bool _consoleEnabled;
|
||
private static bool _packetEnabled;
|
||
private static bool _includeHex;
|
||
private static bool _includeDecoded;
|
||
private static int _maxBodyBytes;
|
||
private static string? _consoleLatest;
|
||
private static string? _consoleArchive;
|
||
private static string? _packetLatest;
|
||
private static string? _packetArchive;
|
||
|
||
// ⛑️⛑️ 长驻 writer —— 见 AppendText 的注释。原来每一行日志都要
|
||
// 「CreateDirectory + new FileStream(Append) + new StreamWriter + 写 + 释放」×2 份文件，
|
||
// 而 FileMode.Append 每次打开都要重新定位到 EOF ⇒ 单行的代价随日志文件变大而变大。
|
||
// 实测：SyncPlayerInfo 那 200 KB 的 hexdump 有 12 541 行，在 09-30 16:50（日志还小）
|
||
// 要 2.8 s，到 10-01 22:08（日志 20 MB）要 6.8~14.1 s —— 而这段时间是**同步**跑在
|
||
// LoginGame handler 里的（RpcContext.NotifyAsync<T> 写完包立刻 RuntimeLogs.Decoded），
|
||
// 收包循环串行 ⇒ 一帧都不读 ⇒ 客户端 TimeScaleAnomaly 判定掉线 ⇒ 重连 ⇒ 又打一份
|
||
// 200 KB 的 hexdump ⇒ 日志更大 ⇒ 更慢。正反馈，永不收敛。
|
||
private static StreamWriter? _consoleLatestWriter;
|
||
private static StreamWriter? _consoleArchiveWriter;
|
||
private static StreamWriter? _packetLatestWriter;
|
||
private static StreamWriter? _packetArchiveWriter;
|
||
|
||
private static TextWriter? _originalOut;
|
||
private static TextWriter? _originalError;
|
||
private static bool _bootstrapConsoleHidden;
|
||
|
||
public static void Initialize(
|
||
string logDirectory,
|
||
string? runId,
|
||
bool consoleEnabled,
|
||
bool packetEnabled,
|
||
bool includeHex,
|
||
bool includeDecoded,
|
||
int maxBodyBytes)
|
||
{
|
||
if (_initialized) return;
|
||
|
||
Directory.CreateDirectory(logDirectory);
|
||
runId = string.IsNullOrWhiteSpace(runId)
|
||
? DateTime.Now.ToString("yyyyMMdd-HHmmss")
|
||
: runId;
|
||
|
||
_consoleEnabled = consoleEnabled;
|
||
_packetEnabled = packetEnabled;
|
||
_includeHex = includeHex;
|
||
_includeDecoded = includeDecoded;
|
||
_maxBodyBytes = Math.Max(0, maxBodyBytes);
|
||
|
||
_consoleLatest = Environment.GetEnvironmentVariable("Ananta_CONSOLE_LOG_LATEST") ?? Environment.GetEnvironmentVariable("DRMK_CONSOLE_LOG_LATEST")
|
||
?? Path.Combine(logDirectory, "console-latest.log");
|
||
_consoleArchive = Environment.GetEnvironmentVariable("Ananta_CONSOLE_LOG_ARCHIVE") ?? Environment.GetEnvironmentVariable("DRMK_CONSOLE_LOG_ARCHIVE")
|
||
?? Path.Combine(logDirectory, $"console-{runId}.log");
|
||
_packetLatest = Environment.GetEnvironmentVariable("DRMK_PACKET_LOG_LATEST")
|
||
?? Path.Combine(logDirectory, "packets-latest.log");
|
||
_packetArchive = Environment.GetEnvironmentVariable("DRMK_PACKET_LOG_ARCHIVE")
|
||
?? Path.Combine(logDirectory, $"packets-{runId}.log");
|
||
|
||
// When launched without Run-All, create a fresh latest/archive pair here.
|
||
if (Environment.GetEnvironmentVariable("DRMK_LOGS_PREPARED") != "1")
|
||
{
|
||
if (_consoleEnabled)
|
||
{
|
||
PrepareFile(_consoleLatest);
|
||
PrepareFile(_consoleArchive);
|
||
}
|
||
if (_packetEnabled)
|
||
{
|
||
PrepareFile(_packetLatest);
|
||
PrepareFile(_packetArchive);
|
||
}
|
||
}
|
||
|
||
// 文件已经 PrepareFile 过（或由 Run-All 预先清空），这里一次性打开并常驻。
|
||
// ⛑ latest 与 archive 指向同一个文件时只开一个 writer —— 两个 Append 流写同一个文件
|
||
// 会各自维护文件指针、互相覆盖（旧代码是每次重写，所以没这个问题）。
|
||
_consoleLatestWriter = _consoleEnabled ? OpenWriter(_consoleLatest) : null;
|
||
_consoleArchiveWriter = _consoleEnabled && !SamePath(_consoleLatest, _consoleArchive)
|
||
? OpenWriter(_consoleArchive) : null;
|
||
_packetLatestWriter = _packetEnabled ? OpenWriter(_packetLatest) : null;
|
||
_packetArchiveWriter = _packetEnabled && !SamePath(_packetLatest, _packetArchive)
|
||
? OpenWriter(_packetArchive) : null;
|
||
|
||
_initialized = true;
|
||
|
||
if (_consoleEnabled)
|
||
{
|
||
_originalOut = Console.Out;
|
||
_originalError = Console.Error;
|
||
_bootstrapConsoleHidden = Environment.GetEnvironmentVariable("DRMK_HIDE_BOOT_LOG") == "1";
|
||
if (_bootstrapConsoleHidden)
|
||
{
|
||
// Run-All already cleared the launcher window. Keep startup diagnostics in the
|
||
// normal console log files without repainting the interactive console.
|
||
Console.SetOut(new MirrorOnlyTextWriter(_originalOut.Encoding, AppendConsole));
|
||
Console.SetError(new MirrorOnlyTextWriter(_originalError.Encoding, AppendConsole));
|
||
}
|
||
else
|
||
{
|
||
Console.SetOut(new TeeTextWriter(_originalOut, AppendConsole));
|
||
Console.SetError(new TeeTextWriter(_originalError, AppendConsole));
|
||
}
|
||
}
|
||
}
|
||
|
||
/// <summary>Restore normal runtime console output after boot diagnostics have completed.</summary>
|
||
public static void EndBootstrapQuietMode()
|
||
{
|
||
if (!_initialized || !_consoleEnabled || !_bootstrapConsoleHidden || _originalOut is null || _originalError is null)
|
||
return;
|
||
|
||
Console.SetOut(new TeeTextWriter(_originalOut, AppendConsole));
|
||
Console.SetError(new TeeTextWriter(_originalError, AppendConsole));
|
||
_bootstrapConsoleHidden = false;
|
||
}
|
||
|
||
public static void Incoming(string scope, RpcPacketKindView kind, uint methodId, int invokeId, ReadOnlySpan<byte> body)
|
||
=> WritePacket(scope, "C2S", kind.ToString().ToUpperInvariant(), methodId, invokeId, null, body);
|
||
|
||
public static void OutgoingNotify(string scope, uint methodId, ReadOnlySpan<byte> body)
|
||
=> WritePacket(scope, "S2C", "NOTIFY", methodId, 0, null, body);
|
||
|
||
public static void OutgoingReturn(string scope, uint methodId, int invokeId, int error, ReadOnlySpan<byte> body)
|
||
=> WritePacket(scope, "S2C", "RETURN", methodId, invokeId, error, body);
|
||
|
||
public static void RawFrame(string scope, string direction, byte mode, ReadOnlySpan<byte> payload, string note)
|
||
{
|
||
if (!_initialized || !_packetEnabled) return;
|
||
AppendPacket($"{Timestamp()} [{scope}] {direction} FRAME mode=0x{mode:X2} note={note} payload={payload.Length}b");
|
||
if (!_includeHex || payload.Length == 0) return;
|
||
var count = _maxBodyBytes == 0 ? payload.Length : Math.Min(payload.Length, _maxBodyBytes);
|
||
foreach (var line in HexDump(payload[..count]))
|
||
AppendPacket($" {line}");
|
||
if (count < payload.Length)
|
||
AppendPacket($" ... truncated {payload.Length - count} bytes (logging.packets.maxBodyBytes={_maxBodyBytes})");
|
||
}
|
||
|
||
public static void Decoded(string scope, string direction, uint methodId, Type contractType, object? value)
|
||
{
|
||
if (!_initialized || !_packetEnabled || !_includeDecoded) return;
|
||
string json;
|
||
try
|
||
{
|
||
json = JsonSerializer.Serialize(value, contractType, JsonOptions);
|
||
}
|
||
catch (Exception ex)
|
||
{
|
||
json = $"<decode-log-failed {ex.GetType().Name}: {ex.Message}>";
|
||
}
|
||
|
||
AppendPacket($"{Timestamp()} [{scope}] {direction} DECODED {RpcMethodNames.Display(methodId)} type={contractType.Name} {json}");
|
||
}
|
||
|
||
private static void WritePacket(
|
||
string scope,
|
||
string direction,
|
||
string kind,
|
||
uint methodId,
|
||
int invokeId,
|
||
int? error,
|
||
ReadOnlySpan<byte> body)
|
||
{
|
||
if (!_initialized || !_packetEnabled) return;
|
||
|
||
var invoke = invokeId != 0 ? $" invoke={invokeId}" : string.Empty;
|
||
var err = error.HasValue ? $" error={error.Value}" : string.Empty;
|
||
AppendPacket($"{Timestamp()} [{scope}] {direction} {kind} {RpcMethodNames.Display(methodId)}{invoke}{err} body={body.Length}b");
|
||
|
||
if (!_includeHex || body.Length == 0) return;
|
||
var count = _maxBodyBytes == 0 ? body.Length : Math.Min(body.Length, _maxBodyBytes);
|
||
foreach (var line in HexDump(body[..count]))
|
||
AppendPacket($" {line}");
|
||
if (count < body.Length)
|
||
AppendPacket($" ... truncated {body.Length - count} bytes (logging.packets.maxBodyBytes={_maxBodyBytes})");
|
||
}
|
||
|
||
private static List<string> HexDump(ReadOnlySpan<byte> body)
|
||
{
|
||
const int width = 16;
|
||
var lines = new List<string>((body.Length + width - 1) / width);
|
||
for (var offset = 0; offset < body.Length; offset += width)
|
||
{
|
||
var len = Math.Min(width, body.Length - offset);
|
||
var slice = body.Slice(offset, len);
|
||
var hex = new StringBuilder(width * 3);
|
||
var ascii = new StringBuilder(width);
|
||
for (var i = 0; i < width; i++)
|
||
{
|
||
if (i < len)
|
||
{
|
||
var b = slice[i];
|
||
hex.Append(b.ToString("X2")).Append(' ');
|
||
ascii.Append(b is >= 32 and <= 126 ? (char)b : '.');
|
||
}
|
||
else
|
||
{
|
||
hex.Append(" ");
|
||
ascii.Append(' ');
|
||
}
|
||
}
|
||
lines.Add($"{offset:X8} {hex}|{ascii}|");
|
||
}
|
||
return lines;
|
||
}
|
||
|
||
private static string Timestamp() => DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss.fff");
|
||
|
||
private static void AppendConsole(string text)
|
||
{
|
||
if (!_initialized || !_consoleEnabled || string.IsNullOrEmpty(text)) return;
|
||
AppendToPair(_consoleLatestWriter, _consoleArchiveWriter, text);
|
||
}
|
||
|
||
private static void AppendPacket(string line)
|
||
=> AppendToPair(_packetLatestWriter, _packetArchiveWriter, line + Environment.NewLine);
|
||
|
||
private static void AppendToPair(StreamWriter? latest, StreamWriter? archive, string text)
|
||
{
|
||
lock (FileLock)
|
||
{
|
||
latest?.Write(text);
|
||
if (!ReferenceEquals(latest, archive)) archive?.Write(text);
|
||
}
|
||
}
|
||
|
||
/// <summary>
|
||
/// 一次性打开日志文件的长驻 writer。
|
||
///
|
||
/// ⛑️ 这里<b>不能</b>回到「每行 new FileStream(FileMode.Append)」的写法：Append 模式每次
|
||
/// 打开都要重新定位到 EOF，单行代价随文件体积线性上涨，20 MB 的 packets 日志上实测
|
||
/// ~0.5 ms/行 ×2 份文件 —— 一个 200 KB 包的 hexdump（12 541 行）就是 10 秒级同步阻塞，
|
||
/// 而它发生在 RPC handler 里（见上面 writer 字段的注释）。
|
||
/// </summary>
|
||
private static StreamWriter? OpenWriter(string? path)
|
||
{
|
||
if (string.IsNullOrWhiteSpace(path)) return null;
|
||
Directory.CreateDirectory(Path.GetDirectoryName(Path.GetFullPath(path))!);
|
||
var stream = new FileStream(path, FileMode.Append, FileAccess.Write, FileShare.ReadWrite | FileShare.Delete);
|
||
// AutoFlush=true：玩家/我自己是边跑边看 console-latest.log 的，不能为了省一次
|
||
// syscall 把尾巴攒在缓冲区里。真正的开销在「打开/关闭」而不在 flush。
|
||
return new StreamWriter(stream, new UTF8Encoding(false)) { AutoFlush = true };
|
||
}
|
||
|
||
private static bool SamePath(string? a, string? b)
|
||
=> !string.IsNullOrWhiteSpace(a) && !string.IsNullOrWhiteSpace(b)
|
||
&& string.Equals(Path.GetFullPath(a), Path.GetFullPath(b), StringComparison.OrdinalIgnoreCase);
|
||
|
||
/// <summary>把长驻 writer 全部 flush（进程正常退出时调用一次，可选）。</summary>
|
||
public static void FlushAll()
|
||
{
|
||
lock (FileLock)
|
||
{
|
||
_consoleLatestWriter?.Flush();
|
||
_consoleArchiveWriter?.Flush();
|
||
_packetLatestWriter?.Flush();
|
||
_packetArchiveWriter?.Flush();
|
||
}
|
||
}
|
||
|
||
private static void PrepareFile(string? path)
|
||
{
|
||
if (string.IsNullOrWhiteSpace(path)) return;
|
||
Directory.CreateDirectory(Path.GetDirectoryName(Path.GetFullPath(path))!);
|
||
File.WriteAllText(path, string.Empty, new UTF8Encoding(false));
|
||
}
|
||
|
||
private sealed class MirrorOnlyTextWriter(Encoding encoding, Action<string> mirror) : TextWriter
|
||
{
|
||
public override Encoding Encoding => encoding;
|
||
|
||
public override void Write(char value) => mirror(value.ToString());
|
||
|
||
public override void Write(string? value)
|
||
{
|
||
if (!string.IsNullOrEmpty(value)) mirror(value);
|
||
}
|
||
|
||
public override void WriteLine(string? value)
|
||
=> mirror((value ?? string.Empty) + Environment.NewLine);
|
||
|
||
public override void WriteLine() => mirror(Environment.NewLine);
|
||
}
|
||
|
||
private sealed class TeeTextWriter(TextWriter original, Action<string> mirror) : TextWriter
|
||
{
|
||
public override Encoding Encoding => original.Encoding;
|
||
|
||
public override void Write(char value)
|
||
{
|
||
original.Write(value);
|
||
mirror(value.ToString());
|
||
}
|
||
|
||
public override void Write(string? value)
|
||
{
|
||
original.Write(value);
|
||
if (!string.IsNullOrEmpty(value)) mirror(value);
|
||
}
|
||
|
||
public override void WriteLine(string? value)
|
||
{
|
||
original.WriteLine(value);
|
||
mirror((value ?? string.Empty) + Environment.NewLine);
|
||
}
|
||
|
||
public override void WriteLine()
|
||
{
|
||
original.WriteLine();
|
||
mirror(Environment.NewLine);
|
||
}
|
||
}
|
||
}
|
||
|
||
/// <summary>Small SDK-only view so the logging layer does not depend on RPC implementation types.</summary>
|
||
public enum RpcPacketKindView
|
||
{
|
||
Invoke,
|
||
Notify,
|
||
Return,
|
||
}
|
||
|
||
/// <summary>Global names populated by RpcRouter.Name; outgoing packets can therefore log symbolic MethodId names too.</summary>
|
||
public static class RpcMethodNames
|
||
{
|
||
private static readonly object Lock = new();
|
||
private static readonly Dictionary<uint, string> Names = new();
|
||
|
||
public static void Register(uint methodId, string name)
|
||
{
|
||
lock (Lock)
|
||
Names.TryAdd(methodId, name);
|
||
}
|
||
|
||
public static string Display(uint methodId)
|
||
{
|
||
lock (Lock)
|
||
return Names.TryGetValue(methodId, out var name)
|
||
? $"{name} [0x{methodId:X8}]"
|
||
: $"0x{methodId:X8}";
|
||
}
|
||
}
|