From f2c636bb1c171f234ee5258242dc4bd1b0382a25 Mon Sep 17 00:00:00 2001 From: Loretta Date: Sun, 12 Jul 2026 19:41:11 +0200 Subject: [PATCH] Improve logger caller resolution and SignalR log reporting Added ResolveBridgeCallerNames to AcLoggerBase for accurate caller detection in ILogger bridge logs using stack trace analysis. Updated debug logging to include caller info via EventId. Enhanced AcLoggerSignalRHub and AcSignaRClientLogItemWriter to log connection lifecycle events and improve connection state reporting. Updated documentation to reflect these changes. --- AyCode.Core/Loggers/AcLoggerBase.cs | 56 ++++++++++++++++++- AyCode.Core/docs/LOGGING/README.md | 4 +- .../SignalRs/AcLoggerSignalRHub.cs | 14 +++++ .../Loggers/AcSignaRClientLogItemWriter.cs | 37 ++++++++---- .../SignalRs/AcBinaryHubProtocol.cs | 10 ++-- 5 files changed, 99 insertions(+), 22 deletions(-) diff --git a/AyCode.Core/Loggers/AcLoggerBase.cs b/AyCode.Core/Loggers/AcLoggerBase.cs index 17f0dbe..406c7f3 100644 --- a/AyCode.Core/Loggers/AcLoggerBase.cs +++ b/AyCode.Core/Loggers/AcLoggerBase.cs @@ -27,6 +27,13 @@ public abstract class AcLoggerBase : IAcLoggerBase /// public bool ShortenCategoryNames { get; set; } = true; + /// + /// If true, ILogger bridge calls without an EventId name resolve the real caller from the stack trace + /// (async state machines unwrapped) instead of showing "Log". Costs a few µs per enabled bridge log; + /// named AC methods (Debug/Info/...) are unaffected. Set false to restore the plain "Log" fallback. + /// + public bool ResolveBridgeCallerNames { get; set; } = true; + protected AcLoggerBase() : this(null) { } @@ -207,8 +214,11 @@ public abstract class AcLoggerBase : IAcLoggerBase var fullMessage = message; var category = ShortenCategoryNames ? GetShortCategoryName(CategoryName) : CategoryName; - // Use eventId.Name as memberName if available, otherwise null (will show as empty, not "Log") - var memberName = !string.IsNullOrEmpty(eventId.Name) ? $"{eventId.Name}:{eventId.Id}" : "Log"; + // Explicit EventId name wins; otherwise resolve the real caller from the stack (opt-out: ResolveBridgeCallerNames). + // EventId.Id 0 means "no id" — show the bare name without the ":0" suffix. + var memberName = !string.IsNullOrEmpty(eventId.Name) + ? eventId.Id != 0 ? $"{eventId.Name}:{eventId.Id}" : eventId.Name + : ResolveBridgeCallerNames ? ResolveCallerFromStackTrace() : "Log"; switch (logLevel) { @@ -249,6 +259,48 @@ public abstract class AcLoggerBase : IAcLoggerBase return lastDot >= 0 ? categoryName[(lastDot + 1)..] : categoryName; } + /// + /// Finds the first stack frame outside the logging infrastructure so ILogger bridge calls + /// (LogDebug/LogInformation/... extensions — these cannot carry CallerMemberName) still show + /// the real caller. Async state machines and lambdas are unwrapped (<Method>d__N.MoveNext -> Method). + /// Only runs when the level is enabled and no EventId name was provided. + /// + private static string ResolveCallerFromStackTrace() + { + var stackTrace = new StackTrace(skipFrames: 1, fNeedFileInfo: false); + var frameCount = Math.Min(stackTrace.FrameCount, 15); + + for (var i = 0; i < frameCount; i++) + { + var method = stackTrace.GetFrame(i)?.GetMethod(); + var declaringType = method?.DeclaringType; + if (method == null || declaringType == null) continue; + + if (declaringType.Namespace?.StartsWith("Microsoft.Extensions.Logging", StringComparison.Ordinal) == true) continue; + if (typeof(AcLoggerBase).IsAssignableFrom(declaringType)) continue; + + // Async state machine: compiler-generated "d__N" type, method is MoveNext. + var typeName = declaringType.Name; + if (typeName.Length > 2 && typeName[0] == '<') + { + var end = typeName.IndexOf('>'); + if (end > 1) return typeName[1..end]; + } + + // Lambda / local function: "b__0"-style method name — unwrap to the containing method. + var methodName = method.Name; + if (methodName.Length > 2 && methodName[0] == '<') + { + var end = methodName.IndexOf('>'); + if (end > 1) return methodName[1..end]; + } + + return methodName; + } + + return "Log"; + } + /// /// Maps Microsoft.Extensions.Logging.LogLevel to AyCode.Core.Loggers.LogLevel. /// diff --git a/AyCode.Core/docs/LOGGING/README.md b/AyCode.Core/docs/LOGGING/README.md index d782ca6..1430888 100644 --- a/AyCode.Core/docs/LOGGING/README.md +++ b/AyCode.Core/docs/LOGGING/README.md @@ -250,7 +250,7 @@ Colored console output. Thread-safe via `static readonly object ForWriterLock`. | Critical | Error | `Error("[CRITICAL] ...")` | | None | Disabled | — (ignored) | -`BeginScope` → no-op `NullScope` (scopes not supported). **ShortenCategoryNames** (default `true`): when MS logging passes fully-qualified type names (e.g. `Microsoft.AspNetCore.SignalR.HubConnectionHandler`), shortens to class name only (`HubConnectionHandler`). +`BeginScope` → no-op `NullScope` (scopes not supported). **ShortenCategoryNames** (default `true`): when MS logging passes fully-qualified type names (e.g. `Microsoft.AspNetCore.SignalR.HubConnectionHandler`), shortens to class name only (`HubConnectionHandler`). **ResolveBridgeCallerNames** (default `true`): bridge calls without an `EventId` name show the real caller resolved from the stack trace (see CallerMemberName Auto-Capture). ### ILoggerProvider @@ -284,7 +284,7 @@ Every named log method has a `*Conditional` counterpart (`InfoConditional`, `Err ### CallerMemberName Auto-Capture -Named log methods use `[CallerMemberName] string? memberName = null` — compiler auto-fills caller name. `ILogger.Log` (MS logging) uses `EventId.Name` if available, else `"Log"`. +Named log methods use `[CallerMemberName] string? memberName = null` — compiler auto-fills caller name. `ILogger.Log` (MS logging) uses `EventId.Name` if available, else resolves the real caller from the stack trace (logging-infrastructure frames skipped, async state machines / lambdas unwrapped to the source method). Opt-out: `ResolveBridgeCallerNames = false` → plain `"Log"` fallback. The stack walk costs a few µs and only runs for enabled bridge logs without an `EventId` name; named AC methods never pay it. ## Key Source Files diff --git a/AyCode.Services.Server/SignalRs/AcLoggerSignalRHub.cs b/AyCode.Services.Server/SignalRs/AcLoggerSignalRHub.cs index 792de80..f02af41 100644 --- a/AyCode.Services.Server/SignalRs/AcLoggerSignalRHub.cs +++ b/AyCode.Services.Server/SignalRs/AcLoggerSignalRHub.cs @@ -11,6 +11,20 @@ public class AcLoggerSignalRHub(TLogger logger) : Hub where TLogger : I { private TLogger _logger = logger; + // Kapcsolat-életciklus markerek: enélkül a szerver-konzolból nem látszik, hogy a kliens-log csatorna + // egyáltalán felépült-e (a néma loggerHub a "sosem csatlakozott" és a "csatlakozott, de nem küld" esetben ugyanúgy néz ki). + public override async Task OnConnectedAsync() + { + _logger.Info($"Logger client connected; ConnectionId: {Context.ConnectionId}"); + await base.OnConnectedAsync(); + } + + public override async Task OnDisconnectedAsync(Exception? exception) + { + _logger.Info($"Logger client disconnected; ConnectionId: {Context.ConnectionId}{(exception == null ? string.Empty : $"; ex: {exception.GetType().Name}: {exception.Message}")}"); + await base.OnDisconnectedAsync(exception); + } + public void AddLogItem(AcLogItem? logItem) { try diff --git a/AyCode.Services/Loggers/AcSignaRClientLogItemWriter.cs b/AyCode.Services/Loggers/AcSignaRClientLogItemWriter.cs index 8e87fa3..0c71a1e 100644 --- a/AyCode.Services/Loggers/AcSignaRClientLogItemWriter.cs +++ b/AyCode.Services/Loggers/AcSignaRClientLogItemWriter.cs @@ -16,6 +16,7 @@ namespace AyCode.Services.Loggers // Spam-védelem: hiba-állapotonként EGY jelentés; sikeres küldés után a kapu újraélesedik, és // helyreálláskor kiírjuk, hány log-item veszett el. (Egyszerű mezők — a torz dupla-jelentés ártalmatlan.) private bool _failureReported; + private bool _connectedReported; private long _droppedCount; public AcSignaRClientLogItemWriter(string fullHubName, AppType appType = AppType.Web, LogLevel logLevel = LogLevel.Detail, string? categoryName = null) : base(appType, logLevel, categoryName) @@ -28,17 +29,33 @@ namespace AyCode.Services.Loggers //.AddMessagePackProtocol(options => options.SerializerOptions = MessagePackSerializerOptions.Standard.WithSecurity(MessagePackSecurity.UntrustedData)) .Build(); - // A .Forget() logger nélkül elnyelné az induló kapcsolat hibáját → jelentő wrapper. - StartConnectionReportedAsync().Forget(); + StartConnection().Forget(); } + /// NEM dob: a kapcsolódási hibát maga jelenti (ReportFailureOnce) — a hívók (ctor fire-and-forget, + /// WriteLogItemCallback) a State-ből látják az eredményt. public async Task StartConnection() { - if (_hubConnection.State == HubConnectionState.Disconnected) - await _hubConnection.StartAsync(); + try + { + if (_hubConnection.State == HubConnectionState.Disconnected) + await _hubConnection.StartAsync(); - if (_hubConnection.State != HubConnectionState.Connected) - await TaskHelper.WaitToAsync(() => _hubConnection.State == HubConnectionState.Connected, 10000, 10, 25); + if (_hubConnection.State != HubConnectionState.Connected) + await TaskHelper.WaitToAsync(() => _hubConnection.State == HubConnectionState.Connected, 10000, 10, 25); + + // Felépülés-marker (kapcsolatonként egyszer) — enélkül a „minden csendben OK" és a „soha el sem indult" + // megkülönböztethetetlen a konzolból. + if (_hubConnection.State == HubConnectionState.Connected && !_connectedReported) + { + _connectedReported = true; + Console.WriteLine($"[{nameof(AcSignaRClientLogItemWriter)}] connected; url: {_fullHubName}"); + } + } + catch (Exception ex) + { + ReportFailureOnce("connect failed", ex); + } } public async Task StopConnection() @@ -79,15 +96,11 @@ namespace AyCode.Services.Loggers } } - private async Task StartConnectionReportedAsync() - { - try { await StartConnection(); } - catch (Exception ex) { ReportFailureOnce("initial connect failed", ex); } - } - /// Hiba-állapotonként EGYSZER ír a Console.Error-ra (nem spamel) — a következő sikeres küldés élesíti újra. private void ReportFailureOnce(string message, Exception? ex) { + _connectedReported = false; // a következő sikeres felépülés újra jelentkezhessen + if (_failureReported) return; _failureReported = true; diff --git a/AyCode.Services/SignalRs/AcBinaryHubProtocol.cs b/AyCode.Services/SignalRs/AcBinaryHubProtocol.cs index 36b87bf..b33b112 100644 --- a/AyCode.Services/SignalRs/AcBinaryHubProtocol.cs +++ b/AyCode.Services/SignalRs/AcBinaryHubProtocol.cs @@ -1383,7 +1383,7 @@ public class AcBinaryHubProtocol : IHubProtocol } [Conditional("DEBUG")] - protected void DebugLogArgument(Type runtimeType, int argBytes, object? value) + protected void DebugLogArgument(Type runtimeType, int argBytes, object? value, [CallerMemberName] string? caller = null) { var kind = value switch { @@ -1393,15 +1393,13 @@ public class AcBinaryHubProtocol : IHubProtocol _ => "scalar" }; - _logger?.LogDebug("WriteArgument runtimeType={RuntimeType} argBytes={ArgBytes} valueIsNull={ValueIsNull} valueTypeKind={Kind}", runtimeType.FullName, argBytes, value == null, kind); - Console.WriteLine($"[DEBUG] WriteArgument runtimeType={runtimeType.FullName} argBytes={argBytes} valueIsNull={value == null} kind={kind}"); + _logger?.LogDebug(new EventId(0, caller), "WriteArgument runtimeType={RuntimeType} argBytes={ArgBytes} valueIsNull={ValueIsNull} valueTypeKind={Kind}", runtimeType.FullName, argBytes, value == null, kind); } [Conditional("DEBUG")] - protected void DebugLogArgument(Type targetType, int argLength, long remaining) + protected void DebugLogArgument(Type targetType, int argLength, long remaining, [CallerMemberName] string? caller = null) { - _logger?.LogDebug("ReadSingleArgument targetType={TargetType} argLength={ArgLength} remaining={Remaining}", targetType.FullName, argLength, remaining); - Console.WriteLine($"[DEBUG] ReadSingleArgument targetType={targetType.FullName} argLength={argLength} remaining={remaining}"); + _logger?.LogDebug(new EventId(0, caller), "ReadSingleArgument targetType={TargetType} argLength={ArgLength} remaining={Remaining}", targetType.FullName, argLength, remaining); } private object?[] ReadArguments(ref SequenceReader r, IReadOnlyList paramTypes, object? headerContext)