| | | 1 | | using System.Diagnostics; |
| | | 2 | | using System.Net.Http.Headers; |
| | | 3 | | using System.Text; |
| | | 4 | | using System.Text.Json; |
| | | 5 | | using System.Text.Json.Nodes; |
| | | 6 | | using System.Text.RegularExpressions; |
| | | 7 | | using Microsoft.Extensions.Hosting; |
| | | 8 | | using Microsoft.Extensions.Options; |
| | | 9 | | |
| | | 10 | | namespace Services.BitrixStockServices; |
| | | 11 | | |
| | | 12 | | public sealed class BitrixStockRunLoggingOptions |
| | | 13 | | { |
| | | 14 | | public const string SectionName = "BitrixStockRunLogging"; |
| | | 15 | | public string? RootPath { get; set; } |
| | | 16 | | public string? FileBrowserBaseUrl { get; set; } |
| | | 17 | | public int WatchdogSeconds { get; set; } = 300; |
| | | 18 | | |
| | | 19 | | /// <summary> |
| | | 20 | | /// Максимум символов тела HTTP-запроса/ответа в technical.ndjson. Полные тела к Bitrix |
| | | 21 | | /// давали ~3 ГБ/день на прогон и забивали NFS. Тела успешных ответов режутся до этого |
| | | 22 | | /// размера; тела ответов с ошибкой (не 2xx) пишутся целиком. 0 — не резать. |
| | | 23 | | /// </summary> |
| | | 24 | | public int MaxLoggedBodyChars { get; set; } = 8192; |
| | | 25 | | } |
| | | 26 | | |
| | | 27 | | public sealed record BitrixStockRunContext( |
| | | 28 | | string RunId, |
| | | 29 | | string Source, |
| | | 30 | | string? ReportId = null, |
| | | 31 | | string? HangfireJobId = null, |
| | | 32 | | string? UserName = null, |
| | | 33 | | string? ClientName = null, |
| | | 34 | | int? Stage = null); |
| | | 35 | | |
| | | 36 | | public interface IBitrixStockRunFileLogger |
| | | 37 | | { |
| | | 38 | | bool HasActiveRun { get; } |
| | | 39 | | IDisposable BeginRun(BitrixStockRunContext context); |
| | | 40 | | Task ProcessAsync(string message, string level = "Information", CancellationToken cancellationToken = default); |
| | | 41 | | Task TechnicalAsync(string eventType, object? data = null, CancellationToken cancellationToken = default); |
| | | 42 | | Task CompleteAsync(bool success, string? error = null, CancellationToken cancellationToken = default); |
| | | 43 | | string GetFileBrowserUrl(DateTime startedAtUtc, string runId); |
| | | 44 | | } |
| | | 45 | | |
| | | 46 | | /// <summary>Файловый аудит BitrixStock. Контекст хранится в AsyncLocal, поэтому другие операции приложения не логируютс |
| | | 47 | | public sealed class BitrixStockRunFileLogger : IBitrixStockRunFileLogger |
| | | 48 | | { |
| | 1 | 49 | | private static readonly AsyncLocal<RunState?> Current = new(); |
| | 1 | 50 | | private static readonly JsonSerializerOptions JsonOptions = new(JsonSerializerDefaults.Web) { WriteIndented = true } |
| | | 51 | | private readonly BitrixStockRunLoggingOptions _options; |
| | | 52 | | private readonly IHostEnvironment _environment; |
| | | 53 | | |
| | 3 | 54 | | public BitrixStockRunFileLogger(IOptions<BitrixStockRunLoggingOptions> options, IHostEnvironment environment) |
| | | 55 | | { |
| | 3 | 56 | | _options = options.Value; |
| | 3 | 57 | | _environment = environment; |
| | 3 | 58 | | } |
| | | 59 | | |
| | 0 | 60 | | public bool HasActiveRun => Current.Value != null; |
| | | 61 | | |
| | | 62 | | public IDisposable BeginRun(BitrixStockRunContext context) |
| | | 63 | | { |
| | 2 | 64 | | if (Current.Value != null) |
| | 0 | 65 | | return NoopScope.Instance; |
| | | 66 | | |
| | 2 | 67 | | var startedAtUtc = DateTime.UtcNow; |
| | 2 | 68 | | var root = string.IsNullOrWhiteSpace(_options.RootPath) |
| | 2 | 69 | | ? Path.Combine(_environment.ContentRootPath, "bitrix-stock-logs") |
| | 2 | 70 | | : _options.RootPath!; |
| | 15 | 71 | | var safeRunId = string.Concat(context.RunId.Select(c => char.IsLetterOrDigit(c) || c is '-' or '_' ? c : '_')); |
| | 2 | 72 | | if (string.IsNullOrWhiteSpace(safeRunId)) safeRunId = Guid.NewGuid().ToString("N"); |
| | 2 | 73 | | var directory = Path.Combine(root, startedAtUtc.ToString("yyyy"), startedAtUtc.ToString("MM"), startedAtUtc.ToSt |
| | 2 | 74 | | Directory.CreateDirectory(directory); |
| | | 75 | | |
| | 2 | 76 | | var state = new RunState(context with { RunId = safeRunId }, startedAtUtc, directory, _options.WatchdogSeconds); |
| | 2 | 77 | | Current.Value = state; |
| | 2 | 78 | | WriteProcessAsync(state, $"Старт: {context.Source}; runId={safeRunId}", "Information", CancellationToken.None).G |
| | 2 | 79 | | WriteTechnicalAsync(state, "run.started", new { context = state.Context, directory }, CancellationToken.None).Ge |
| | 2 | 80 | | WriteSummaryAsync(state, null, CancellationToken.None).GetAwaiter().GetResult(); |
| | 2 | 81 | | state.StartWatchdog(this); |
| | 2 | 82 | | return new Scope(this, state); |
| | | 83 | | } |
| | | 84 | | |
| | | 85 | | public Task ProcessAsync(string message, string level = "Information", CancellationToken cancellationToken = default |
| | 1 | 86 | | Current.Value is { } state ? WriteProcessAsync(state, message, level, cancellationToken) : Task.CompletedTask; |
| | | 87 | | |
| | | 88 | | public Task TechnicalAsync(string eventType, object? data = null, CancellationToken cancellationToken = default) => |
| | 1 | 89 | | Current.Value is { } state ? WriteTechnicalAsync(state, eventType, data, cancellationToken) : Task.CompletedTask |
| | | 90 | | |
| | | 91 | | public async Task CompleteAsync(bool success, string? error = null, CancellationToken cancellationToken = default) |
| | | 92 | | { |
| | 2 | 93 | | if (Current.Value is not { } state) return; |
| | 2 | 94 | | state.Completed = true; |
| | 2 | 95 | | state.Success = success; |
| | 2 | 96 | | state.Error = error; |
| | 2 | 97 | | state.CompletedAtUtc = DateTime.UtcNow; |
| | 2 | 98 | | await WriteProcessAsync(state, success ? "Завершено успешно" : $"Завершено с ошибкой: {error}", success ? "Infor |
| | 2 | 99 | | await WriteTechnicalAsync(state, "run.completed", new { success, error, durationMs = (state.CompletedAtUtc.Value |
| | 2 | 100 | | await WriteSummaryAsync(state, error, cancellationToken); |
| | 2 | 101 | | } |
| | | 102 | | |
| | | 103 | | public string GetFileBrowserUrl(DateTime startedAtUtc, string runId) |
| | | 104 | | { |
| | 1 | 105 | | if (string.IsNullOrWhiteSpace(_options.FileBrowserBaseUrl)) return string.Empty; |
| | 4 | 106 | | var safeRunId = Uri.EscapeDataString(string.Concat(runId.Select(c => char.IsLetterOrDigit(c) || c is '-' or '_' |
| | 1 | 107 | | return $"{_options.FileBrowserBaseUrl!.TrimEnd('/')}/{startedAtUtc:yyyy'/'MM'/'dd}/{safeRunId}/"; |
| | | 108 | | } |
| | | 109 | | |
| | | 110 | | private async Task WriteProcessAsync(RunState state, string message, string level, CancellationToken ct) |
| | | 111 | | { |
| | 6 | 112 | | state.Touch(message); |
| | 6 | 113 | | await state.Gate.WaitAsync(ct); |
| | 12 | 114 | | try { await File.AppendAllTextAsync(Path.Combine(state.Directory, "process.log"), $"{DateTime.UtcNow:O} [{level} |
| | 6 | 115 | | finally { state.Gate.Release(); } |
| | 6 | 116 | | } |
| | | 117 | | |
| | | 118 | | private async Task WriteTechnicalAsync(RunState state, string eventType, object? data, CancellationToken ct) |
| | | 119 | | { |
| | 6 | 120 | | state.Touch(eventType); |
| | 6 | 121 | | var line = JsonSerializer.Serialize(new { timestampUtc = DateTime.UtcNow, eventType, runId = state.Context.RunId |
| | 6 | 122 | | await state.Gate.WaitAsync(ct); |
| | 12 | 123 | | try { await File.AppendAllTextAsync(Path.Combine(state.Directory, "technical.ndjson"), line + Environment.NewLin |
| | 6 | 124 | | finally { state.Gate.Release(); } |
| | 6 | 125 | | } |
| | | 126 | | |
| | | 127 | | private async Task WriteSummaryAsync(RunState state, string? error, CancellationToken ct) |
| | | 128 | | { |
| | 4 | 129 | | var summary = new { context = state.Context, startedAtUtc = state.StartedAtUtc, completedAtUtc = state.Completed |
| | 4 | 130 | | await state.Gate.WaitAsync(ct); |
| | 8 | 131 | | try { await File.WriteAllTextAsync(Path.Combine(state.Directory, "summary.json"), JsonSerializer.Serialize(summa |
| | 4 | 132 | | finally { state.Gate.Release(); } |
| | 4 | 133 | | } |
| | | 134 | | |
| | | 135 | | private async Task WatchdogAsync(RunState state) |
| | | 136 | | { |
| | 3 | 137 | | if (state.Completed || DateTime.UtcNow - state.LastActivityUtc < state.WatchdogTimeout) return; |
| | 1 | 138 | | await WriteProcessAsync(state, $"Нет прогресса более {state.WatchdogTimeout.TotalMinutes:0} мин.; операция: {sta |
| | 1 | 139 | | await WriteTechnicalAsync(state, "watchdog.stalled", new { operation = state.CurrentOperation, elapsedMs = (Date |
| | 2 | 140 | | } |
| | | 141 | | |
| | | 142 | | internal static string? Redact(string? value) |
| | | 143 | | { |
| | 14 | 144 | | if (string.IsNullOrEmpty(value)) return value; |
| | 8 | 145 | | return Regex.Replace(value, "(?i)(authorization|api[-_]?key|password|secret|token|cookie|connection\\s*string)(\ |
| | | 146 | | } |
| | | 147 | | |
| | | 148 | | internal static object? RedactObject(object? value) |
| | | 149 | | { |
| | 6 | 150 | | if (value == null) return null; |
| | 6 | 151 | | var node = JsonSerializer.SerializeToNode(value, JsonOptions); |
| | 6 | 152 | | RedactNode(node); |
| | 6 | 153 | | return node; |
| | | 154 | | } |
| | | 155 | | |
| | | 156 | | private static void RedactNode(JsonNode? node) |
| | | 157 | | { |
| | 33 | 158 | | if (node is JsonObject obj) |
| | 76 | 159 | | foreach (var item in obj.ToList()) |
| | 58 | 160 | | if (IsSecret(item.Key)) obj[item.Key] = "***"; else RedactNode(item.Value); |
| | 33 | 161 | | if (node is JsonArray array) |
| | 0 | 162 | | foreach (var item in array) RedactNode(item); |
| | 33 | 163 | | } |
| | | 164 | | |
| | 29 | 165 | | private static bool IsSecret(string key) => key.Contains("authorization", StringComparison.OrdinalIgnoreCase) |
| | 29 | 166 | | || key.Contains("api", StringComparison.OrdinalIgnoreCase) && key.Contains("key", StringComparison.OrdinalIgnore |
| | 29 | 167 | | || key.Contains("password", StringComparison.OrdinalIgnoreCase) || key.Contains("secret", StringComparison.Ordin |
| | 29 | 168 | | || key.Contains("token", StringComparison.OrdinalIgnoreCase) || key.Contains("cookie", StringComparison.OrdinalI |
| | 29 | 169 | | || key.Contains("connection", StringComparison.OrdinalIgnoreCase) && key.Contains("string", StringComparison.Ord |
| | | 170 | | |
| | 2 | 171 | | private sealed class Scope(BitrixStockRunFileLogger logger, RunState state) : IDisposable |
| | | 172 | | { |
| | | 173 | | public void Dispose() |
| | | 174 | | { |
| | 2 | 175 | | state.Timer?.Dispose(); |
| | 2 | 176 | | if (!state.Completed) logger.CompleteAsync(false, "Запуск завершён без финального статуса").GetAwaiter().Get |
| | 4 | 177 | | if (ReferenceEquals(Current.Value, state)) Current.Value = null; |
| | 2 | 178 | | } |
| | | 179 | | } |
| | 0 | 180 | | private sealed class NoopScope : IDisposable { public static readonly NoopScope Instance = new(); public void Dispos |
| | 2 | 181 | | private sealed class RunState(BitrixStockRunContext context, DateTime startedAtUtc, string directory, int watchdogSe |
| | | 182 | | { |
| | 14 | 183 | | public BitrixStockRunContext Context { get; } = context; |
| | 8 | 184 | | public DateTime StartedAtUtc { get; } = startedAtUtc; |
| | 22 | 185 | | public string Directory { get; } = directory; |
| | 34 | 186 | | public SemaphoreSlim Gate { get; } = new(1, 1); |
| | 9 | 187 | | public TimeSpan WatchdogTimeout { get; } = TimeSpan.FromSeconds(Math.Max(1, watchdogSeconds)); |
| | 17 | 188 | | public DateTime LastActivityUtc { get; private set; } = startedAtUtc; |
| | 16 | 189 | | public string CurrentOperation { get; private set; } = "start"; |
| | 6 | 190 | | public bool Completed { get; set; } |
| | 6 | 191 | | public bool? Success { get; set; } |
| | 2 | 192 | | public string? Error { get; set; } |
| | 8 | 193 | | public DateTime? CompletedAtUtc { get; set; } |
| | 4 | 194 | | public Timer? Timer { get; private set; } |
| | 36 | 195 | | public void Touch(string operation) { LastActivityUtc = DateTime.UtcNow; CurrentOperation = operation; } |
| | 4 | 196 | | public void StartWatchdog(BitrixStockRunFileLogger logger) => Timer = new Timer(async _ => await logger.Watchdog |
| | | 197 | | } |
| | | 198 | | } |
| | | 199 | | |
| | | 200 | | public sealed class BitrixStockRunHttpLoggingHandler( |
| | | 201 | | IBitrixStockRunFileLogger logger, |
| | | 202 | | IOptions<BitrixStockRunLoggingOptions> options) : DelegatingHandler |
| | | 203 | | { |
| | | 204 | | private readonly int _maxBodyChars = Math.Max(0, options.Value.MaxLoggedBodyChars); |
| | | 205 | | |
| | | 206 | | protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellat |
| | | 207 | | { |
| | | 208 | | if (!logger.HasActiveRun) return await base.SendAsync(request, cancellationToken); |
| | | 209 | | var stopwatch = Stopwatch.StartNew(); |
| | | 210 | | var requestBody = request.Content == null ? null : await request.Content.ReadAsStringAsync(cancellationToken); |
| | | 211 | | await logger.TechnicalAsync("http.request", new { method = request.Method.Method, url = request.RequestUri?.ToSt |
| | | 212 | | try |
| | | 213 | | { |
| | | 214 | | var response = await base.SendAsync(request, cancellationToken); |
| | | 215 | | var responseBody = response.Content == null ? null : await response.Content.ReadAsStringAsync(cancellationTo |
| | | 216 | | // Тело ответа с ошибкой пишем целиком — именно оно нужно при разборе сбоя. |
| | | 217 | | var loggedBody = response.IsSuccessStatusCode ? Cap(responseBody) : responseBody; |
| | | 218 | | await logger.TechnicalAsync("http.response", new { statusCode = (int)response.StatusCode, durationMs = stopw |
| | | 219 | | return response; |
| | | 220 | | } |
| | | 221 | | catch (Exception ex) |
| | | 222 | | { |
| | | 223 | | await logger.TechnicalAsync("http.error", new { exception = ex.GetType().Name, message = ex.Message, duratio |
| | | 224 | | throw; |
| | | 225 | | } |
| | | 226 | | } |
| | | 227 | | |
| | | 228 | | private string? Cap(string? body) |
| | | 229 | | { |
| | | 230 | | if (_maxBodyChars == 0 || string.IsNullOrEmpty(body) || body.Length <= _maxBodyChars) |
| | | 231 | | return body; |
| | | 232 | | return string.Concat(body.AsSpan(0, _maxBodyChars), $"… [обрезано, всего {body.Length} симв.]"); |
| | | 233 | | } |
| | | 234 | | |
| | | 235 | | private static Dictionary<string, string> Headers(HttpHeaders headers) => headers.ToDictionary(h => h.Key, h => stri |
| | | 236 | | } |