ASP.NET Core – Protokollmeldungen an die Datenbank im Hintergrund

ASP.NET Core – Protokollmeldungen an die Datenbank im Hintergrund

Ich habe über die Anmeldung in ASP.NET gelesen, als ich auf diese Anweisung zur Anmeldung bei der Datenbank gestoßen bin:

In diesem Artikel zeige ich, wie man diese Hintergrund-Datenbank-Logger-Idee implementiert. Zuerst zeige ich das Design und dann den Code.

Gestaltung

Wir können Microsofts Hintergrund-Datenbank-Logger-Idee implementieren, indem wir das Consumer/Producer-Muster mit einem Hintergrunddienst verwenden. Um sicherzustellen, dass dies gut skaliert, fügen wir Protokollmeldungen in großen Mengen in die Datenbank ein.

Ich werde auf dieses Design im Detail eingehen, aber zuerst ist hier das Designdiagramm:

Mit dem Verbraucher/Erzeuger-Muster haben Sie einen oder mehrere Erzeuger, die Nachrichten in eine gemeinsam genutzte Warteschlange einreihen. Sie haben einen oder mehrere Verbraucher, die Nachrichten aus der gemeinsam genutzten Warteschlange entfernen und verarbeiten. In unserem Fall haben wir mehrere Producer (alles, was protokolliert, meistens Controller) und einen einzelnen Consumer.

In ASP.NET können Sie gehostete Dienste hinzufügen, die im Hintergrund ausgeführt werden. Diese werden als Hintergrunddienste bezeichnet. Wir verwenden einen Hintergrunddienst für zwei Zwecke:Er enthält die gemeinsam genutzte Warteschlange und fungiert als Verbraucher.

Die Produzenten müssen lediglich einer Log()-Methode ausgesetzt werden. Sie müssen nicht wissen, dass sie einen Hintergrunddienst verwenden oder dass er sich in der Datenbank anmeldet. Aus diesem Grund verwenden wir die ILoggerService-Schnittstelle.

Da es mehrere Produzenten geben kann, können mehrere Protokollnachrichten gleichzeitig eingehen. Das Ausführen vieler einzelner INSERT-Anweisungen kann die Systemleistung beeinträchtigen. Stattdessen fügen wir die Nachrichten massenhaft ein. Für die Masseneinfügung muss der Konsument in der Lage sein, aus der Warteschlange stapelweise zu lesen.

Code

In diesem Abschnitt zeige ich den Code für das oben gezeigte Design. Ich werde dies von außen nach innen und den Hintergrunddienst zuletzt erstellen.

In diesem Code verwende ich Console.WriteLine(). Ich führe den Dienst mit einer Konsolenschnittstelle aus, damit ich leicht sehen kann, was vor sich geht.

ILoggerService und ein Controller, der ihn verwendet

Das Wichtigste zuerst, wir müssen ILoggerService hinzufügen. Es hat sich bewährt, für Schnittstellen anstelle von Implementierungen zu codieren. Die Produzenten müssen lediglich Zugriff auf die Methode Log() haben. Sie müssen nichts über die konkrete Umsetzung wissen.

public interface ILoggerService
{
	void Log(LogLevel logLevel, string message);
}
Code language: C# (cs)

Hinweis:Ich verwende den integrierten ILogger nicht. Es hat eine riesige Menge an Methoden, und ich wollte sie nicht im Hintergrunddienst implementieren müssen.

Hier ist ein Beispiel für einen Controller, der Nachrichten protokolliert. Es muss eine ILoggerService-Abhängigkeit eingefügt werden.

[Route("[controller]")]
[ApiController]
public class RecipesController : ControllerBase
{
	private readonly ILoggerService Logger;
	public RecipesController(ILoggerService logger)
	{
		Logger = logger;
	}

	[HttpGet("{id}")]
	public string Get(int id)
	{
		Logger.Log(LogLevel.Debug, $"GET /Recipes/{id}");
		return "recipe";
	}
}
Code language: C# (cs)

Protokoll-Repository zum Masseneinfügen

Wir möchten die Protokollmeldungen massenhaft einfügen. Jedes Mal, wenn Sie mit einer Datenbank interagieren, ist es eine gute Idee, das Repository-Muster zu implementieren. Mit diesem Muster kapseln Sie die Datenbank-Interaktionslogik in einer Repository-Klasse.

Zuerst müssen wir die LogMessage-Modellklasse hinzufügen:

public class LogMessage
{
	public int ThreadId { get; set; }
	public string Message { get; set; }
	public DateTimeOffset Timestamp { get; set; }
}
Code language: C# (cs)

Da wir als Nächstes SqlBulkCopy verwenden möchten und .NET Core verwenden, müssen wir das Nuget-Paket „System.Data.SqlClient“ installieren. Führen Sie dazu den folgenden Befehl aus (Hinweis:Dies verwendet View> Other Windows> Package Manager Console) :

Install-Package System.Data.SqlClient
Code language: PowerShell (powershell)

Jetzt können wir die Klasse LogRepository implementieren. Es führt eine Masseneinfügung mit SqlBulkCopy durch.

Immer wenn Sie mit einer externen Abhängigkeit wie einer Datenbank interagieren, ist es eine gute Idee, sie fehlertolerant zu machen. In diesem Fall versuchen wir, dies widerstandsfähig zu machen, indem wir einige vorübergehende SQL-Ausnahmen abfangen und die Masseneinfügung einige Male wiederholen.

Hier ist die LogRepository-Klasse:

using System.Data;
using System.Data.SqlClient;

public class LogRepository : ILogRepository
{
	private const string TABLE = "Log";
	private readonly string ConnectionString;
	private readonly HashSet<int> transientSqlErrors = new HashSet<int>()
	{
		-2, 258, 4060
	};
	private const int MAX_RETRIES = 3;
	private const int RETRY_SECONDS = 5;
	public LogRepository(string connectionString)
	{
		ConnectionString = connectionString;
	}
	public async Task Insert(List<LogMessage> logMessages)
	{
		DataTable table = new DataTable();
		table.TableName = TABLE;

		table.Columns.Add(nameof(LogMessage.Timestamp), typeof(DateTimeOffset));
		table.Columns.Add(nameof(LogMessage.Message), typeof(string));
		table.Columns.Add(nameof(LogMessage.ThreadId), typeof(int));
		foreach (var logMessage in logMessages)
		{
			var row = table.NewRow();

			row[nameof(LogMessage.Timestamp)] = logMessage.Timestamp;
			row[nameof(LogMessage.Message)] = logMessage.Message ?? (object)DBNull.Value;
			row[nameof(LogMessage.ThreadId)] = logMessage.ThreadId;

			table.Rows.Add(row);
		}

		await BulkInsertWithRetries(table);
	}

	private async Task BulkInsertWithRetries(DataTable table)
	{
		int attempts = 1;
		while (true)
		{
			try
			{
				using (var sqlBulkCopy = new SqlBulkCopy(ConnectionString))
				{
					sqlBulkCopy.DestinationTableName = table.TableName;
					await sqlBulkCopy.WriteToServerAsync(table);
					return;
				}
			}
			catch (SqlException sqlEx)
			when (transientSqlErrors.Contains(sqlEx.Number) && attempts <= MAX_RETRIES)
			{
				Console.WriteLine($"Transient SQL error. Retrying in {RETRY_SECONDS} seconds");
				await Task.Delay(TimeSpan.FromSeconds(RETRY_SECONDS));
				attempts++;
			}
		}
	}
}
Code language: C# (cs)

Hinweis:Wir könnten in diesem Szenario einen Ansatz mit Tabellenwertparametern (TVP) verwenden, anstatt eine Masseneinfügung durchzuführen. Das Hauptziel hier ist ein satzbasierter Ansatz, damit wir das System nicht mit vielen einzelnen Einfügungen zuspammen. Beide Ansätze (TVP und Masseneinfügung) funktionieren dafür gut.

Hintergrunddienst mit einer Protokollwarteschlange

Schließlich können wir die Hintergrunddienstklasse hinzufügen und DatabaseLoggerService nennen. Damit dies als Hintergrunddienst ausgeführt wird, müssen wir BackgroundService.

implementieren

Wir implementieren das Consumer/Producer-Muster, indem wir eine asynchrone Warteschlange aus System.Threading.Channels hinzufügen. Die ILoggerService.Log()-Methode ermöglicht Produzenten, Protokollmeldungen in die Warteschlange einzureihen. Wir implementieren die Consumer-Schleife in ExecuteAsync() (eine Methode von BackgroundService).

Hier ist die DatabaseLoggerService-Klasse:

using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;
using System.Threading.Channels;

public class DatabaseLoggerService : BackgroundService, ILoggerService
{
	private readonly Channel<LogMessage> logMessageQueue;
	private readonly IHostApplicationLifetime HostApplicationLifetime;
	private const int MAX_BATCH_SIZE = 10;
	private readonly ILogRepository LogRepository;
	public DatabaseLoggerService(ILogRepository logRepository, IHostApplicationLifetime hostApplicationLifetime)
	{
		logMessageQueue = Channel.CreateUnbounded<LogMessage>();
		LogRepository = logRepository;
		HostApplicationLifetime = hostApplicationLifetime;
	}
	public async override Task StopAsync(CancellationToken cancellationToken)
	{
		await base.StopAsync(cancellationToken);
	}
	protected async override Task ExecuteAsync(CancellationToken stoppingToken)
	{
		while(!stoppingToken.IsCancellationRequested)
		{

			try
			{
				Console.WriteLine("Waiting for log messages");
				var batch = await GetBatch(stoppingToken);

				Console.WriteLine($"Got a batch with {batch.Count}(s) log messages. Bulk inserting them now.");

				//Let non-retryable errors from this bubble up and crash the service
				await LogRepository.Insert(batch);
			}
			catch (TaskCanceledException)
			{
				Console.WriteLine("Stopping token was canceled, which means the service is shutting down.");
				return;
			}
			catch (Exception ex)
			{
				Console.WriteLine($"Fatal exception in database logger. Crashing service. Error={ex}");
				HostApplicationLifetime.StopApplication();
				return;
			}
		}
	}
	public void Log(LogLevel logLevel, string message)
	{
		//The reason to use Writer.TryWrite() is because it's synchronous.
		//We want the logging to be as fast as possible for the client, so
		//we don't want the overhead of async

		//Note: We're using an unbounded Channel, so TryWrite() *should* only fail 
		//if we call writer.Complete().
		//Guard against it anyway


		var logMessage = new LogMessage()
		{
			Message = message,
			ThreadId = System.Threading.Thread.CurrentThread.ManagedThreadId,
			Timestamp = DateTimeOffset.Now
		};

		if (!logMessageQueue.Writer.TryWrite(logMessage))
		{
			throw new InvalidOperationException("Failed to write the log message");
		}
	}
	private async Task<List<LogMessage>> GetBatch(CancellationToken cancellationToken)
	{
		await logMessageQueue.Reader.WaitToReadAsync(cancellationToken);

		var batch = new List<LogMessage>();

		while (batch.Count < MAX_BATCH_SIZE && logMessageQueue.Reader.TryRead(out LogMessage message))
		{
			batch.Add(message);
		}

		return batch;
	}
}
Code language: C# (cs)

Die Produzenten rufen Log() synchron auf. Dies ist schnell, da die Nachricht lediglich in die Warteschlange gestellt wird.

Die Consumer-Schleife liest einen Stapel von Nachrichten aus der Warteschlange und wartet dann auf die Masseneinfügung. Ich würde nicht vorschlagen, zu feuern und die Masseneinfügung zu vergessen. Zum einen wirkt das Warten auf den Abschluss als Drosselungsmechanismus. Sie führen immer nur eine Masseneinfügung auf einmal durch. Zweitens vereinfacht es die Fehlerbehandlung.

Beachten Sie, dass dies StopApplication() aufruft, wenn eine Ausnahme von LogRepository auftaucht. Wie im LogRepository-Abschnitt erwähnt, wird es einige Male wiederholt, wenn es vorübergehende SQL-Ausnahmen gibt. Bei jeder anderen Art von Fehler oder wenn die maximale Wiederholungszahl überschritten wird, wird es ausgelöst. Dies löst ein ordnungsgemäßes Herunterfahren des gesamten Dienstes aus und stürzt nicht nur den Hintergrunddienst ab. Es gibt definitiv andere Möglichkeiten, dies zu handhaben – wie das Protokollieren in eine Fallback-Datei – aber ich habe mich für den einfachsten Ansatz entschieden, mit der Annahme, dass dieses Protokollieren kritisch ist und der Dienst anhalten sollte, wenn er nicht protokolliert.

Hinweis:TryWrite() könnte fehlschlagen, aber es ist sehr unwahrscheinlich (wenn nicht unmöglich), wenn ein unbegrenzter Kanal verwendet wird (und nichts versetzt den Kanal in einen abgeschlossenen Zustand).

Registrierung der Dienste

Sie müssen DatabaseLoggerService als Singleton registrieren (damit eine Abhängigkeit in die Controller und alle anderen Hersteller injiziert werden kann) und auch als gehosteter Dienst, damit er als Hintergrunddienst ausgeführt wird.

public class Startup
{
	//rest of class
	public void ConfigureServices(IServiceCollection services)
	{
		//rest of method

		services.AddSingleton<ILogRepository, LogRepository>(_ 
			=> new LogRepository(Configuration.GetConnectionString("Default")));

		services.AddSingleton<ILoggerService, DatabaseLoggerService>();

		services.AddHostedService(sp => sp.GetService<ILoggerService>() as DatabaseLoggerService);
	   
	}
}
Code language: C# (cs)

Standardverbindungszeichenfolge in appsettings.json

Wir können einen Platzhalter für die Verbindungszeichenfolge in appsettings.json hinzufügen und dann der echten Verbindungszeichenfolge ein Benutzergeheimnis hinzufügen.

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft": "Warning",
      "Microsoft.Hosting.Lifetime": "Information"
    }
  },
  "AllowedHosts": "*",
  "ConnectionStrings": {
    "Default": "The connection string is defined in the user secrets file"
  }
}

Code language: JSON / JSON with Comments (json)

Führen Sie es aus

Um dies zu testen und in Aktion zu sehen, führen Sie den ASP.NET-Dienst aus und senden Sie gleichzeitig Anforderungen. Überprüfen Sie die Protokolltabelle in der Datenbank, um sicherzustellen, dass die Nachrichten eingefügt wurden.

Um zu sehen, wie Masseneinfügungen funktionieren, verwenden Sie den folgenden Testclient, der Unmengen gleichzeitiger Anfragen sendet:

static async Task Main(string[] args)
{
	var httpClient = new HttpClient();
	var go = new ManualResetEventSlim();


	for (int i = 1; i <= 77; i++)
	{
		var num = i; //capture for closure
		Task.Run(async () =>
		{
			Console.WriteLine($"Num {num} waiting");
			go.Wait();
			Console.WriteLine($"Num {num} going");
			var response = await httpClient.GetAsync($"https://localhost:12345/Recipes/{num}");
			response.EnsureSuccessStatusCode();
			
			Console.WriteLine($"Num {num} done");

		});
	}

	go.Set();

	Console.ReadLine();

}
Code language: C# (cs)

Hinweis:Ich habe versucht, gleichzeitig Anfragen mit Postman zu senden, aber es war zu langsam.

Sie können nicht nur sehen, dass die Masseneinfügungen funktionieren, Sie können auch eine vorübergehende SQL-Ausnahme auslösen, um zu sehen, dass Wiederholungsversuche durchgeführt werden. Der einfachste Weg, dies zu tun, besteht darin, die Datenbank manuell offline zu setzen, zu warten, bis sie den vorübergehenden Fehler meldet, und die Datenbank dann manuell wieder online zu setzen.

Hier ist ein Beispiel dafür, wie es aussieht, wenn Sie Folgendes ausführen:

CommandLoop starting
Waiting for log messages
Got a batch with 7(s) log messages. Bulk inserting them now.
Transient SQL error. Retrying in 5 seconds
Waiting for log messages
Got a batch with 10(s) log messages. Bulk inserting them now.
Waiting for log messages
Got a batch with 10(s) log messages. Bulk inserting them now.
Waiting for log messages
Got a batch with 10(s) log messages. Bulk inserting them now.
Waiting for log messages
Got a batch with 10(s) log messages. Bulk inserting them now.
Waiting for log messages
Got a batch with 10(s) log messages. Bulk inserting them now.
Waiting for log messages
Got a batch with 10(s) log messages. Bulk inserting them now.
Waiting for log messages
Got a batch with 10(s) log messages. Bulk inserting them now.
Waiting for log messagesCode language: plaintext (plaintext)

Der Consumer liest zwischen 1-10 Nachrichten aus der Warteschlange. Wenn 10 Nachrichten verfügbar sind, werden alle 10 gelesen. Andernfalls werden so viele wie möglich gelesen. Beachten Sie zunächst, dass nur 7 Nachrichten gelesen wurden. Das liegt daran, dass zu diesem Zeitpunkt nur 7 Nachrichten in der Warteschlange verfügbar waren. Danach konnte es jedes Mal 10 Nachrichten lesen.

Beachten Sie auch, dass es den vorübergehenden SQL-Fehler erkannt, 5 Sekunden gewartet und es erneut versucht hat. Bei einem erneuten Versuch war es erfolgreich.

Quellcode

Der vollständige Quellcode für den in diesem Artikel gezeigten Hintergrund-Datenbanklogger ist hier verfügbar:https://github.com/makolyte/aspdotnet-background-dblogger