【C#】信頼性の高いログ処理システムの設計と実装：バッファリング、リトライ、シャットダウン処理まで
2024-08-21
2024-08-21
まず、ログファイルの保存形式について説明します。このシステムでは、ログファイルは時間単位で分割され、ディレクトリ構造内に整理されて保存されます。例えば、ログは次のような構造で保存されます。
logs/
├── YYYY/
│ ├── MM/
│ │ ├── DD/
│ │ │ ├── log_YYYY-MM-DD_00.log
│ │ │ ├── log_YYYY-MM-DD_01.log
│ │ │ ├── log_YYYY-MM-DD_02.log
│ │ │ └── ...
│ │ │ └── log_YYYY-MM-DD_23.log
ログファイルの命名規則
各ログファイルの名前は log_YYYY-MM-DD_HH.log という形式で保存されます。この命名規則により、ログは年、月、日、時間ごとに整理され、特定の期間のログを容易に検索できます。
例: log_2023-01-01_14.log は、2023年1月1日の14時に生成されたログファイルです。
ログ内容のフォーマット
各ログファイルには、タイムスタンプとその時点で発生したログメッセージが保存されます。具体的なログエントリは次のような形式です。
2023-01-01 14:05:32 [INFO] Program.cs:Main:32 - Application started.
2023-01-01 14:06:15 [ERROR] Database.cs:Connect:87 - Failed to connect to database.
このように、ログには次の情報が含まれます。
- タイムスタンプ:
2023-01-01 14:05:32 - ログレベル:
[INFO]や[ERROR] - 呼び出し元情報:
Program.cs:Main:32は、ファイル名、メソッド名、行番号を表します。 - メッセージ内容:
Application started.やFailed to connect to database.など、ログの具体的なメッセージです。
信頼性の高いログ処理システムの設計
バッファリングされたログ書き込み
ログの書き込みは、システム全体のパフォーマンスを最大限に高めるために、メモリにバッファリングされます。BufferedFileLogger クラスは、ログを一時的にメモリに格納し、一定数のログが蓄積されるか、一定の時間が経過すると、ファイルに書き込みます。
これにより、ディスクI/Oを最小限に抑え、頻繁な書き込みがシステムパフォーマンスに与える影響を軽減します。
public class BufferedFileLogger : ILogger, IDisposable
{
private readonly string _logFilePath;
private readonly BlockingCollection<string> _logQueue;
private readonly Thread _loggerThread;
private int _batchSize;
private TimeSpan _flushInterval;
private volatile bool _disposed = false;
public BufferedFileLogger(string logFilePath, int batchSize = 100, int flushIntervalSeconds = 5, int maxQueueSize = 10000)
{
_logFilePath = logFilePath;
_batchSize = batchSize;
_flushInterval = TimeSpan.FromSeconds(flushIntervalSeconds);
_logQueue = new BlockingCollection<string>(new ConcurrentQueue<string>(), maxQueueSize);
_loggerThread = new Thread(ProcessLogQueue) { IsBackground = true };
_loggerThread.Start();
}
// ログの処理と書き込みロジックは後述
}
ログのメタデータ（デバッグ情報）の付加
ログのトラブルシューティングを迅速に行うため、各ログにはソースコードのファイル名、メソッド名、行番号といったデバッグ情報が自動的に付加されます。この情報は、[CallerFilePath], [CallerMemberName], [CallerLineNumber] 属性を使用して取得されます。
public void LogError(string message, Exception ex = null, [CallerFilePath] string file = "", [CallerMemberName] string member = "", [CallerLineNumber] int line = 0)
{
Log("ERROR", message, ex, file, member, line);
}
private void Log(string level, string message, Exception ex = null, string file = "", string member = "", int line = 0)
{
if (_disposed) return;
var logMessage = $"{DateTime.Now:yyyy-MM-dd HH:mm:ss} [{level}] {Path.GetFileName(file)}:{member}:{line} - {message}";
if (ex != null)
{
logMessage += $"\nException: {ex.GetType().Name}\nMessage: {ex.Message}\nStack Trace: {ex.StackTrace}";
}
if (!_logQueue.TryAdd(logMessage))
{
Console.WriteLine("Warning: Log queue is full. Some log messages may be lost.");
}
}
リトライポリシーの導入
ログの書き込みが失敗した場合、一時的なエラー（例えばI/Oエラーなど）をリトライし、最終的に失敗した場合はバックアップファイルに書き込みます。RetryPolicy クラスは、このリトライ機構を実装しています。
public class RetryPolicy
{
public int MaxRetries { get; }
public TimeSpan InitialDelay { get; }
public RetryPolicy(int maxRetries, TimeSpan initialDelay)
{
MaxRetries = maxRetries;
InitialDelay = initialDelay;
}
public T Execute<T>(Func<T> action, Func<Exception, bool> shouldRetry = null)
{
shouldRetry ??= (_ => true); // デフォルトではすべての例外でリトライ
for (int attempt = 1; attempt <= MaxRetries; attempt++)
{
try
{
return action();
}
catch (Exception ex)
{
if (attempt == MaxRetries || !shouldRetry(ex))
{
throw new RetryExceededException($"Action failed after {attempt} attempts", ex);
}
Thread.Sleep(TimeSpan.FromTicks(InitialDelay.Ticks * attempt));
}
}
throw new InvalidOperationException("This code should never be reached");
}
}
シャットダウン処理
アプリケーション終了時に、すべてのログが確実にファイルに書き込まれるように、シャットダウン処理を実装します。Dispose メソッド内で、残ったログが確実にフラッシュされ、ログスレッドが正しく終了することを確認します。
public void Dispose()
{
if (_disposed) return;
_disposed = true;
_logQueue.CompleteAdding();
try
{
const int shutdownTimeoutSeconds = 10;
if (!_loggerThread.Join(TimeSpan.FromSeconds(shutdownTimeoutSeconds)))
{
Console.WriteLine($"Logger thread did not shut down gracefully within {shutdownTimeoutSeconds} seconds.");
LogWarning($"Logger thread shutdown timed out after {shutdownTimeoutSeconds} seconds.");
// 追加のシャットダウン戦略
for (int i = 0; i < 3; i++) // 追加で3回試行
{
if (_loggerThread.Join(TimeSpan.FromSeconds(2)))
{
Console.WriteLine("Logger thread shut down successfully after additional attempts.");
break;
}
}
if (_loggerThread.IsAlive)
{
Console.WriteLine("Logger thread is still alive. Consider implementing a forceful termination strategy.");
}
}
// 残っているログのフラッシュ
List<string> remainingLogs = new List<string>();
while (_logQueue.TryTake(out string logMessage))
{
remainingLogs.Add(logMessage);
}
if (remainingLogs.Count > 0)
{
Console.WriteLine($"Flushing {remainingLogs.Count} remaining log messages.");
FlushLogs(remainingLogs);
}
}
catch (Exception ex)
{
Console.WriteLine($"Error during logger shutdown: {ex.Message}\nStack Trace: {ex.StackTrace}");
}
finally
{
_logQueue.Dispose();
}
}
ログシステムの使用例
最後に、ログシステムの使用例を紹介します。このコードでは、ログのバッファリング、リトライ処理、シャットダウン処理がすべて組み合わされています。
class Program
{
static void Main()
{
using (var logger = new BufferedFileLogger("log_retriever.log"))
{
var retryPolicy = new RetryPolicy(5, TimeSpan.FromSeconds(2));
var retriever = new LogRetriever(@"C:\logs", logger, retryPolicy);
var startDate = new DateTime(2023, 1, 1, 0, 0, 0);
var endDate = new DateTime(2023, 12, 31, 23, 59, 59);
try
{
var sortedLogs = retriever.RetrieveAndSortLogs(startDate, endDate);
foreach (var log in sortedLogs)
{
Console.WriteLine($"{log.Timestamp:yyyy-MM-dd HH:mm:ss} {log.Content}");
}
// ロガーの設定の動的な変更
logger.UpdateSettings(batchSize: 200, flushIntervalSeconds: 10);
}
catch (Exception ex)
{
logger.LogError("An error occurred while retrieving and sorting logs", ex);
Console.WriteLine($"An error occurred: {ex.Message}\nStack Trace: {ex.StackTrace}");
}
}
}
}
全体のコード
using System;
using System.IO;
using System.Linq;
using System.Collections.Generic;
using System.Text.RegularExpressions;
using System.Globalization;
using System.Threading;
using System.Collections.Concurrent;
using System.Runtime.CompilerServices;
public class LogEntry
{
public DateTime Timestamp { get; set; }
public string Content { get; set; }
}
public class LogRetriever
{
private readonly string _baseDirectory;
private static readonly Regex LogFileRegex = new Regex(@"log_(\d{4}-\d{2}-\d{2}_\d{2})\.log", RegexOptions.Compiled);
private const string DateFormat = "yyyy-MM-dd HH:mm:ss";
private const string FileNameDateFormat = "yyyy-MM-dd_HH";
private readonly ILogger _logger;
private readonly RetryPolicy _retryPolicy;
public LogRetriever(string baseDirectory, ILogger logger, RetryPolicy retryPolicy = null)
{
_baseDirectory = baseDirectory;
_logger = logger ?? throw new ArgumentNullException(nameof(logger));
_retryPolicy = retryPolicy ?? new RetryPolicy(3, TimeSpan.FromSeconds(1));
}
public IEnumerable<LogEntry> RetrieveAndSortLogs(DateTime startDate, DateTime endDate)
{
var logFiles = Directory.EnumerateFiles(_baseDirectory, "log_*.log", SearchOption.AllDirectories)
.Select(f => new { Path = f, Date = ParseFileDate(f) })
.Where(f => f.Date.HasValue && f.Date.Value >= startDate.Date && f.Date.Value <= endDate.Date)
.OrderBy(f => f.Date);
foreach (var file in logFiles)
{
_logger.LogInfo($"Processing file: {file.Path}");
foreach (var entry in ProcessFile(file.Path, startDate, endDate))
{
yield return entry;
}
_logger.LogInfo($"Completed processing file: {file.Path}");
}
}
private DateTime? ParseFileDate(string filePath)
{
var match = LogFileRegex.Match(Path.GetFileName(filePath));
if (match.Success && DateTime.TryParseExact(match.Groups[1].Value, FileNameDateFormat, CultureInfo.InvariantCulture, DateTimeStyles.None, out var fileDate))
{
return fileDate;
}
_logger.LogWarning($"Invalid file name format: {filePath}");
return null;
}
private IEnumerable<LogEntry> ProcessFile(string filePath, DateTime startDate, DateTime endDate)
{
return _retryPolicy.Execute(() =>
{
try
{
return File.ReadLines(filePath)
.Select((line, index) => new { Line = line, Index = index })
.Select(item => ParseLogLine(item.Line, filePath, item.Index))
.Where(entry => entry != null && entry.Timestamp >= startDate && entry.Timestamp <= endDate)
.ToList();
}
catch (IOException ex)
{
_logger.LogError($"I/O error processing file {filePath}: {ex.Message}", ex);
throw;
}
catch (UnauthorizedAccessException ex)
{
_logger.LogError($"Access denied to file {filePath}: {ex.Message}", ex);
throw;
}
catch (Exception ex)
{
_logger.LogError($"Unexpected error processing file {filePath}: {ex.Message}", ex);
throw;
}
});
}
private LogEntry ParseLogLine(string line, string filePath, int lineNumber)
{
var parts = line.Split(new[] { ' ' }, 2);
if (parts.Length == 2 && DateTime.TryParseExact(parts[0], DateFormat, CultureInfo.InvariantCulture, DateTimeStyles.None, out var timestamp))
{
return new LogEntry { Timestamp = timestamp, Content = parts[1] };
}
_logger.LogWarning($"Invalid log line format in file {filePath}, line {lineNumber}: {line}");
return null;
}
}
public class BufferedFileLogger : ILogger, IDisposable
{
private readonly string _logFilePath;
private readonly BlockingCollection<string> _logQueue;
private readonly Thread _loggerThread;
private int _batchSize;
private TimeSpan _flushInterval;
private volatile bool _disposed = false;
private readonly object _settingsLock = new object();
private readonly RetryPolicy _retryPolicy;
private readonly string _backupLogFilePath;
public BufferedFileLogger(string logFilePath, int batchSize = 100, int flushIntervalSeconds = 5, int maxQueueSize = 10000)
{
_logFilePath = logFilePath;
_backupLogFilePath = logFilePath + ".backup";
_batchSize = batchSize;
_flushInterval = TimeSpan.FromSeconds(flushIntervalSeconds);
_logQueue = new BlockingCollection<string>(new ConcurrentQueue<string>(), maxQueueSize);
_loggerThread = new Thread(ProcessLogQueue) { IsBackground = true };
_retryPolicy = new RetryPolicy(3, TimeSpan.FromSeconds(1));
_loggerThread.Start();
}
public void UpdateSettings(int? batchSize = null, int? flushIntervalSeconds = null)
{
lock (_settingsLock)
{
if (batchSize.HasValue) _batchSize = batchSize.Value;
if (flushIntervalSeconds.HasValue) _flushInterval = TimeSpan.FromSeconds(flushIntervalSeconds.Value);
}
}
public void LogError(string message, Exception ex = null, [CallerFilePath] string file = "", [CallerMemberName] string member = "", [CallerLineNumber] int line = 0)
{
Log("ERROR", message, ex, file, member, line);
}
public void LogWarning(string message, [CallerFilePath] string file = "", [CallerMemberName] string member = "", [CallerLineNumber] int line = 0)
{
Log("WARNING", message, null, file, member, line);
}
public void LogInfo(string message, [CallerFilePath] string file = "", [CallerMemberName] string member = "", [CallerLineNumber] int line = 0)
{
Log("INFO", message, null, file, member, line);
}
private void Log(string level, string message, Exception ex = null, string file = "", string member = "", int line = 0)
{
if (_disposed) return;
var logMessage = $"{DateTime.Now:yyyy-MM-dd HH:mm:ss} [{level}] {Path.GetFileName(file)}:{member}:{line} - {message}";
if (ex != null)
{
logMessage += $"\nException: {ex.GetType().Name}\nMessage: {ex.Message}\nStack Trace: {ex.StackTrace}";
}
if (!_logQueue.TryAdd(logMessage))
{
Console.WriteLine("Warning: Log queue is full. Some log messages may be lost.");
}
}
private void ProcessLogQueue()
{
List<string> logBatch = new List<string>();
while (!_disposed)
{
try
{
int currentBatchSize;
TimeSpan currentFlushInterval;
lock (_settingsLock)
{
currentBatchSize = _batchSize;
currentFlushInterval = _flushInterval;
}
while (logBatch.Count < currentBatchSize && _logQueue.TryTake(out string logMessage, currentFlushInterval))
{
logBatch.Add(logMessage);
}
if (logBatch.Count > 0)
{
FlushLogs(logBatch);
logBatch.Clear();
}
}
catch (Exception ex)
{
Console.WriteLine($"Error in log processing thread: {ex.Message}\nStack Trace: {ex.StackTrace}");
}
}
}
private void FlushLogs(List<string> logBatch)
{
try
{
_retryPolicy.Execute(() =>
{
File.AppendAllLines(_logFilePath, logBatch);
return true;
}, ex => !(ex is UnauthorizedAccessException));
}
catch (RetryExceededException ex)
{
Console.WriteLine($"Failed to write logs to {_logFilePath}. Attempting to write to backup file. Remaining logs: {logBatch.Count}. Final error: {ex.InnerException?.Message}");
Console.WriteLine($"Stack Trace: {ex.InnerException?.StackTrace}");
try
{
File.AppendAllLines(_backupLogFilePath, logBatch);
Console.WriteLine($"Successfully wrote logs to backup file: {_backupLogFilePath}");
}
catch (Exception backupEx)
{
Console.WriteLine($"Failed to write logs to backup file: {backupEx.Message}");
// At this point, consider storing logs in memory or using a different persistence strategy
}
}
}
public void Dispose()
{
if (_disposed) return;
_disposed = true;
_logQueue.CompleteAdding();
try
{
const int shutdownTimeoutSeconds = 10;
if (!_loggerThread.Join(TimeSpan.FromSeconds(shutdownTimeoutSeconds)))
{
Console.WriteLine($"Logger thread did not shut down gracefully within {shutdownTimeoutSeconds} seconds.");
LogWarning($"Logger thread shutdown timed out after {shutdownTimeoutSeconds} seconds.");
// Implement additional shutdown strategies if necessary
}
// Flush any remaining logs
List<string> remainingLogs = new List<string>();
while (_logQueue.TryTake(out string logMessage))
{
remainingLogs.Add(logMessage);
}
if (remainingLogs.Count > 0)
{
Console.WriteLine($"Flushing {remainingLogs.Count} remaining log messages.");
FlushLogs(remainingLogs);
}
}
catch (Exception ex)
{
Console.WriteLine($"Error during logger shutdown: {ex.Message}\nStack Trace: {ex.StackTrace}");
}
finally
{
_logQueue.Dispose();
}
}
}
public class RetryPolicy
{
public int MaxRetries { get; }
public TimeSpan InitialDelay { get; }
public RetryPolicy(int maxRetries, TimeSpan initialDelay)
{
MaxRetries = maxRetries;
InitialDelay = initialDelay;
}
public T Execute<T>(Func<T> action, Func<Exception, bool> shouldRetry = null)
{
shouldRetry ??= (_ => true); // Default to retry on all exceptions if not specified
for (int attempt = 1; attempt <= MaxRetries; attempt++)
{
try
{
return action();
}
catch (Exception ex)
{
if (attempt == MaxRetries || !shouldRetry(ex))
{
throw new RetryExceededException($"Action failed after {attempt} attempts", ex);
}
Thread.Sleep(TimeSpan.FromTicks(InitialDelay.Ticks * attempt));
}
}
throw new InvalidOperationException("This code should never be reached");
}
}
public class RetryExceededException : Exception
{
public RetryExceededException(string message, Exception innerException) : base(message, innerException) { }
}
// Usage example
class Program
{
static void Main()
{
using (var logger = new BufferedFileLogger("log_retriever.log"))
{
var retryPolicy = new RetryPolicy(5, TimeSpan.FromSeconds(2));
var retriever = new LogRetriever(@"C:\logs", logger, retryPolicy);
var startDate = new DateTime(2023, 1, 1, 0, 0, 0);
var endDate = new DateTime(2023, 12, 31, 23, 59, 59);
try
{
var sortedLogs = retriever.RetrieveAndSortLogs(startDate, endDate);
foreach (var log in sortedLogs)
{
Console.WriteLine($"{log.Timestamp:yyyy-MM-dd HH:mm:ss} {log.Content}");
}
// Example of updating logger settings
logger.UpdateSettings(batchSize: 200, flushIntervalSeconds: 10);
}
catch (Exception ex)
{
logger.LogError("An error occurred while retrieving and sorting logs", ex);
Console.WriteLine($"An error occurred: {ex.Message}\nStack Trace: {ex.StackTrace}");
}
}
}
}
まとめ
本記事では、信頼性の高いログ処理システムの設計と実装について説明しました。バッファリングされたログ処理、リトライポリシー、メタデータの付加、シャットダウン処理など、実際の運用環境で発生しうる課題に対応するための工夫を紹介しました。
このシステムを使用することで、パフォーマンスと信頼性を両立し、ログ処理の効率を最大化することができます。ログが重要なシステムの健全性を保つための手段であることを忘れず、適切に管理することが重要です。