| | | 1 | | using System.Diagnostics; |
| | | 2 | | using ArturRios.Logging.Interfaces; |
| | | 3 | | using Microsoft.Extensions.DependencyInjection; |
| | | 4 | | using Microsoft.Extensions.Logging; |
| | | 5 | | |
| | | 6 | | namespace ArturRios.Logging.Adapter; |
| | | 7 | | |
| | | 8 | | /// <summary> |
| | | 9 | | /// Bridges <see cref="ILogger"/> onto <see cref="IStateLogger"/>, so code written against |
| | | 10 | | /// Microsoft.Extensions.Logging reaches this library's loggers. |
| | | 11 | | /// </summary> |
| | | 12 | | /// <remarks> |
| | | 13 | | /// <para> |
| | | 14 | | /// Each call resolves <see cref="IStateLogger"/> from a fresh dependency injection scope, so a scoped |
| | | 15 | | /// dependency of the state logger is isolated per log entry. The correlation id therefore does not travel |
| | | 16 | | /// through the scope; it is read from the ambient <see cref="Activity"/> instead. |
| | | 17 | | /// </para> |
| | | 18 | | /// <para> |
| | | 19 | | /// <see cref="Activity"/> is the correlation primitive of the platform, not of any one hosting model: an |
| | | 20 | | /// ASP.NET Core request has one, and so does a worker, a console app or a test. Reading the id from there |
| | | 21 | | /// is what lets this library log correlated entries without depending on ASP.NET Core. |
| | | 22 | | /// </para> |
| | | 23 | | /// </remarks> |
| | | 24 | | /// <param name="services">The provider used to resolve the state logger.</param> |
| | | 25 | | /// <exception cref="ArgumentNullException"><paramref name="services"/> is <c>null</c>.</exception> |
| | 4024 | 26 | | public class MicrosoftLoggerAdapter(IServiceProvider services) : ILogger |
| | | 27 | | { |
| | | 28 | | /// <summary> |
| | | 29 | | /// A correlation id set explicitly by a caller, overriding the ambient activity's. Held in an |
| | | 30 | | /// <see cref="AsyncLocal{T}"/> so it flows with the execution context — per request under a server, |
| | | 31 | | /// per logical operation anywhere else — rather than leaking across concurrent work. |
| | | 32 | | /// </summary> |
| | 1 | 33 | | private static readonly AsyncLocal<string?> Override = new(); |
| | | 34 | | |
| | 4024 | 35 | | private readonly IServiceProvider _services = services ?? throw new ArgumentNullException(nameof(services)); |
| | | 36 | | |
| | | 37 | | /// <summary> |
| | | 38 | | /// Gets or sets the correlation id stamped on log entries. |
| | | 39 | | /// </summary> |
| | | 40 | | /// <value> |
| | | 41 | | /// The id set explicitly on this property, or the trace id of <see cref="Activity.Current"/> when none |
| | | 42 | | /// was set, or <c>null</c> when there is no ambient activity either. |
| | | 43 | | /// </value> |
| | | 44 | | /// <remarks> |
| | | 45 | | /// Setting it establishes the id for the current execution context and everything that flows from it. |
| | | 46 | | /// <c>ArturRios.Util.WebApi</c>'s <c>TraceActivityMiddleware</c> starts a W3C activity per request and |
| | | 47 | | /// derives its own trace id from exactly this activity, so under that middleware the value read here is |
| | | 48 | | /// the same one the middleware publishes — with no ASP.NET Core dependency on this side. |
| | | 49 | | /// </remarks> |
| | | 50 | | public string? TraceId |
| | | 51 | | { |
| | 4020 | 52 | | get => Override.Value ?? Activity.Current?.TraceId.ToString(); |
| | 4008 | 53 | | set => Override.Value = value; |
| | | 54 | | } |
| | | 55 | | |
| | | 56 | | /// <inheritdoc /> |
| | 0 | 57 | | public IDisposable BeginScope<TState>(TState state) where TState : notnull => NullScope.Instance; |
| | | 58 | | |
| | | 59 | | /// <inheritdoc /> |
| | 4017 | 60 | | public bool IsEnabled(LogLevel logLevel) => logLevel != LogLevel.None; |
| | | 61 | | |
| | | 62 | | /// <inheritdoc /> |
| | | 63 | | public void Log<TState>( |
| | | 64 | | LogLevel logLevel, |
| | | 65 | | EventId eventId, |
| | | 66 | | TState state, |
| | | 67 | | Exception? exception, |
| | | 68 | | Func<TState, Exception?, string>? formatter) |
| | | 69 | | { |
| | 4015 | 70 | | if (!IsEnabled(logLevel)) |
| | 0 | 71 | | return; |
| | | 72 | | |
| | 4015 | 73 | | var message = formatter != null ? formatter(state!, exception) : state?.ToString() ?? string.Empty; |
| | | 74 | | |
| | | 75 | | // Resolve the scoped IStateLogger (if not registered you'll get null) |
| | 4015 | 76 | | using var scope = _services.CreateScope(); |
| | 4015 | 77 | | var stateLogger = scope.ServiceProvider.GetService<IStateLogger>(); |
| | | 78 | | |
| | 4015 | 79 | | if (stateLogger is null) |
| | | 80 | | { |
| | | 81 | | // No IStateLogger registered — nothing to forward to |
| | 1 | 82 | | return; |
| | | 83 | | } |
| | | 84 | | |
| | | 85 | | // Enrich state with caller info if not present so StateLogger.ResolveCallerInfo can pick it up. |
| | 4014 | 86 | | object? enrichedState = state; |
| | 4014 | 87 | | if (!StateContainsCallerInfo(state)) |
| | | 88 | | { |
| | 4012 | 89 | | var (filePath, memberName) = FindCallerFromStack(); |
| | 4012 | 90 | | var kvList = new List<KeyValuePair<string, object>>(); |
| | | 91 | | |
| | 4012 | 92 | | if (state is IEnumerable<KeyValuePair<string, object>> existingPairs) |
| | | 93 | | { |
| | 8026 | 94 | | foreach (var kv in existingPairs) |
| | | 95 | | { |
| | 1 | 96 | | kvList.Add(kv); |
| | | 97 | | } |
| | | 98 | | } |
| | | 99 | | |
| | 4012 | 100 | | kvList.Add(new KeyValuePair<string, object>("CallerFilePath", filePath)); |
| | 4012 | 101 | | kvList.Add(new KeyValuePair<string, object>("CallerMemberName", memberName)); |
| | 4012 | 102 | | kvList.Add(new KeyValuePair<string, object>("OriginalMessage", message)); |
| | | 103 | | |
| | 4012 | 104 | | enrichedState = kvList.ToArray(); |
| | | 105 | | } |
| | | 106 | | |
| | | 107 | | // The ambient correlation id, whether set explicitly or carried by the current activity, reaches the |
| | | 108 | | // output through IStateLogger.TraceId — a plain property. A singleton state logger is shared by every |
| | | 109 | | // entry, so the id is set, used and put back under a lock on the instance: otherwise a concurrent entry |
| | | 110 | | // could be written with this entry's id, and a later entry without an ambient id would inherit it. |
| | | 111 | | // A scoped state logger is a fresh instance per entry here, so the lock is never contended. |
| | 4014 | 112 | | lock (stateLogger) |
| | | 113 | | { |
| | 4014 | 114 | | var previousTraceId = stateLogger.TraceId; |
| | | 115 | | |
| | 4014 | 116 | | if (TraceId is { } ambientTraceId) |
| | | 117 | | { |
| | 4006 | 118 | | stateLogger.TraceId = ambientTraceId; |
| | | 119 | | } |
| | | 120 | | |
| | | 121 | | try |
| | | 122 | | { |
| | 4014 | 123 | | Forward(stateLogger, logLevel, message, exception, enrichedState); |
| | 4014 | 124 | | } |
| | | 125 | | finally |
| | | 126 | | { |
| | 4014 | 127 | | stateLogger.TraceId = previousTraceId; |
| | 4014 | 128 | | } |
| | | 129 | | } |
| | 4015 | 130 | | } |
| | | 131 | | |
| | | 132 | | private static void Forward(IStateLogger stateLogger, LogLevel logLevel, string message, Exception? exception, |
| | | 133 | | object? enrichedState) |
| | | 134 | | { |
| | 4014 | 135 | | if (exception is not null) |
| | | 136 | | { |
| | 1 | 137 | | stateLogger.Exception(exception, enrichedState); |
| | | 138 | | } |
| | | 139 | | |
| | | 140 | | switch (logLevel) |
| | | 141 | | { |
| | | 142 | | case LogLevel.Trace: |
| | 0 | 143 | | stateLogger.Trace(message, enrichedState); |
| | 0 | 144 | | break; |
| | | 145 | | case LogLevel.Debug: |
| | 0 | 146 | | stateLogger.Debug(message, enrichedState); |
| | 0 | 147 | | break; |
| | | 148 | | case LogLevel.Information: |
| | 4013 | 149 | | stateLogger.Info(message, enrichedState); |
| | 4013 | 150 | | break; |
| | | 151 | | case LogLevel.Warning: |
| | 0 | 152 | | stateLogger.Warn(message, enrichedState); |
| | 0 | 153 | | break; |
| | | 154 | | case LogLevel.Error: |
| | 1 | 155 | | stateLogger.Error(message, enrichedState); |
| | 1 | 156 | | break; |
| | | 157 | | case LogLevel.Critical: |
| | 0 | 158 | | stateLogger.Critical(message, enrichedState); |
| | 0 | 159 | | break; |
| | | 160 | | case LogLevel.None: |
| | | 161 | | default: |
| | 0 | 162 | | throw new ArgumentOutOfRangeException(nameof(logLevel), logLevel, null); |
| | | 163 | | } |
| | | 164 | | } |
| | | 165 | | |
| | | 166 | | private static bool StateContainsCallerInfo(object? state) |
| | | 167 | | { |
| | 4014 | 168 | | if (state is not IEnumerable<KeyValuePair<string, object?>> pairs) |
| | | 169 | | { |
| | 0 | 170 | | return false; |
| | | 171 | | } |
| | | 172 | | |
| | 8028 | 173 | | bool hasFile = false, hasMember = false; |
| | | 174 | | |
| | 8036 | 175 | | foreach (var (k, v) in pairs) |
| | | 176 | | { |
| | 5 | 177 | | if (v is null) |
| | | 178 | | { |
| | | 179 | | continue; |
| | | 180 | | } |
| | | 181 | | |
| | 5 | 182 | | if (!hasFile && (string.Equals(k, "CallerFilePath", StringComparison.OrdinalIgnoreCase) || |
| | 5 | 183 | | string.Equals(k, "FilePath", StringComparison.OrdinalIgnoreCase) || |
| | 5 | 184 | | string.Equals(k, "callerFilePath", StringComparison.OrdinalIgnoreCase))) |
| | | 185 | | { |
| | 2 | 186 | | hasFile = true; |
| | | 187 | | } |
| | | 188 | | |
| | 5 | 189 | | if (!hasMember && (string.Equals(k, "CallerMemberName", StringComparison.OrdinalIgnoreCase) || |
| | 5 | 190 | | string.Equals(k, "MemberName", StringComparison.OrdinalIgnoreCase) || |
| | 5 | 191 | | string.Equals(k, "Method", StringComparison.OrdinalIgnoreCase) || |
| | 5 | 192 | | string.Equals(k, "callerMemberName", StringComparison.OrdinalIgnoreCase))) |
| | | 193 | | { |
| | 2 | 194 | | hasMember = true; |
| | | 195 | | } |
| | | 196 | | |
| | 5 | 197 | | if (hasFile && hasMember) |
| | 2 | 198 | | return true; |
| | | 199 | | } |
| | | 200 | | |
| | 4012 | 201 | | return false; |
| | 2 | 202 | | } |
| | | 203 | | |
| | | 204 | | private static (string filePath, string memberName) FindCallerFromStack() |
| | | 205 | | { |
| | | 206 | | try |
| | | 207 | | { |
| | 4012 | 208 | | var st = new StackTrace(skipFrames: 1, fNeedFileInfo: false); |
| | | 209 | | |
| | 72166 | 210 | | for (var i = 0; i < st.FrameCount; i++) |
| | | 211 | | { |
| | 32082 | 212 | | var frame = st.GetFrame(i); |
| | 32082 | 213 | | var method = frame?.GetMethod(); |
| | 32082 | 214 | | if (method == null) |
| | | 215 | | continue; |
| | 32082 | 216 | | var declaring = method.DeclaringType; |
| | 32082 | 217 | | if (declaring == null) |
| | | 218 | | continue; |
| | | 219 | | |
| | 32082 | 220 | | var ns = declaring.Namespace ?? string.Empty; |
| | | 221 | | |
| | | 222 | | // Skip known logging infrastructure namespaces so we find the real caller |
| | | 223 | | // ArturRios.Logging is this library's own namespace. The predecessor of this check named |
| | | 224 | | // ArturRios.Common.Logging, which no longer exists, so nothing here was ever skipped and the |
| | | 225 | | // frame reported as the caller was MicrosoftLoggerAdapter.Log itself. |
| | 32082 | 226 | | if (ns.StartsWith("Microsoft.Extensions.Logging", StringComparison.Ordinal) || |
| | 32082 | 227 | | ns.Equals("ArturRios.Logging", StringComparison.Ordinal) || |
| | 32082 | 228 | | ns.StartsWith("ArturRios.Logging.", StringComparison.Ordinal) || |
| | 32082 | 229 | | ns.StartsWith("System.", StringComparison.Ordinal)) |
| | | 230 | | { |
| | | 231 | | continue; |
| | | 232 | | } |
| | | 233 | | |
| | 11 | 234 | | var memberName = method.Name; |
| | 11 | 235 | | var filePath = declaring.FullName ?? declaring.Name; |
| | | 236 | | |
| | 11 | 237 | | return (filePath, memberName); |
| | | 238 | | } |
| | 4001 | 239 | | } |
| | 0 | 240 | | catch |
| | | 241 | | { |
| | | 242 | | // swallow any errors and fall through to unknowns |
| | 0 | 243 | | } |
| | | 244 | | |
| | 4001 | 245 | | return ("unknown", "unknown"); |
| | 11 | 246 | | } |
| | | 247 | | |
| | | 248 | | private class NullScope : IDisposable |
| | | 249 | | { |
| | 0 | 250 | | public static NullScope Instance { get; } = new(); |
| | 0 | 251 | | public void Dispose() { } |
| | | 252 | | } |
| | | 253 | | } |