ASP.NET Core 源碼學習之 Logging[4]:FileProvider

前面幾章介紹了 ASP.NET Core Logging 系統的配置和使用，而對於 Provider ，微軟也提供了 Console, Debug, EventSource, TraceSource 等，但是沒有我們最常用的 FilePrivider，而比較流行的 Log4Net , NLog 等也對 ASP.NET Core 的 Logging 系統提供了擴展，但是太過於復雜，而且他們本身就是一個完整的日志系統，功能上會有較多的重合，所以我們不妨自己動手，寫一個輕量級的完全基於 ASP.NET Core Logging 系統的 FileProvider。

IMessageWriter

首先定義一個日志寫入接口：

public interface IMessageWriter : IDisposable
{
    Task WriteMessagesAsync(string message, CancellationToken cancellationToken = default(CancellationToken));
}

只有一個異步的寫日志方法，用來將日志寫入到文件或者隊列中。

FileWriter

IMessageWriter 最核心的實現，將日志寫入到文件中。

public class FileWriter : IMessageWriter, IDisposable
{
    ...

    public FileWriter(string path, long? fileSizeLimit = null)
    {
        ...
        _underlyingStream = System.IO.File.Open(path, FileMode.Append, FileAccess.Write, FileShare.ReadWrite);
        _output = new StreamWriter(_underlyingStream, new UTF8Encoding(encoderShouldEmitUTF8Identifier: false));
    }

    public async Task WriteMessagesAsync(string message, CancellationToken cancellationToken)
    {
        if (_maxFileSize > 0 && _underlyingStream.Length > _maxFileSize)
        {
            return;
        }
        await _output.WriteAsync(message);
        FlushToDisk();
    }

    ...
}

其實現很簡單，就是使用最基本的文件 Stream 來寫入文件 ，並立即刷新到磁盤。

BatchingWriter

上面 FileWriter 最大的弊端就是每次寫日志都要進行一次文件IO操作，效率較低，可以使用定時器，來定時刷新到磁盤，來提高性能。不過，在 Logging.AzureAppServices 中發現了更好的實現方式，即使用批量提交：

public class BatchingWriter : IMessageWriter, IDisposable
{
    ...

    public BatchingWriter(IMessageWriter writer, TimeSpan interval, int? batchSize, int? queueSize)
    {
        ...
        Start();
    }

    private void Start()
    {
        _messageQueue = _queueSize == null ?
            new BlockingCollection<string>(new ConcurrentQueue<string>()) :
            new BlockingCollection<string>(new ConcurrentQueue<string>(), _queueSize.Value);

        _cancellationTokenSource = new CancellationTokenSource();
        _outputTask = Task.Factory.StartNew<Task>(
            ProcessLogQueue,
            null,
            TaskCreationOptions.LongRunning);
    }

    private async Task ProcessLogQueue(object state)
    {
        StringBuilder currentBatch = new StringBuilder();
        while (!_cancellationTokenSource.IsCancellationRequested)
        {
            var limit = _batchSize ?? int.MaxValue;
            while (limit > 0 && _messageQueue.TryTake(out var message))
            {
                currentBatch.Append(message);
                limit--;
            }
            if (currentBatch.Length > 0)
            {
                try
                {
                    await _writer.WriteMessagesAsync(currentBatch.ToString(), _cancellationTokenSource.Token);
                }
                catch
                {
                    // ignored
                }
            }
            await IntervalAsync(_interval, _cancellationTokenSource.Token);
        }
    }

    protected virtual Task IntervalAsync(TimeSpan interval, CancellationToken cancellationToken)
    {
        return Task.Delay(interval, cancellationToken);
    }

    private void Stop()
    {
        ...
    }

    public Task WriteMessagesAsync(string message, CancellationToken cancellationToken)
    {
        if (!_messageQueue.IsAddingCompleted)
        {
            try
            {
                _messageQueue.Add(message, _cancellationTokenSource.Token);
            }
            catch
            {
                //cancellation token canceled or CompleteAdding called
            }
        }
        return Task.CompletedTask;
    }

    ...
}

首先定義了一個並發隊列，每次寫入只需要將日志保存到隊列當中，通過配置獲取執行周期來定期從隊列中取出日志，再使用上面的 FileWriter 來持久化到磁盤。

RollingFileWriter

使用上面兩個類，已滿足了最基本的寫日志功能，但是在 Log4Net 等日志框架中，我們經常會按一定的頻度滾動日志記錄文件，也就是 RollingFile 功能，可實現將每天或每小時的日志保存到一個文件中，按文件大小進行滾動等功能。

首先是定義了一個 RollingFrequency 類，用來根據配置的文件名，來獲取滾動頻率，比如我們指定日志文件名為 Logs\my-{Date}.log，則表示每天滾動一次。

public class RollingFrequency
{
    public static readonly RollingFrequency Date = new RollingFrequency("Date", "yyyyMMdd", TimeSpan.FromDays(1));
    public static readonly RollingFrequency Hour = new RollingFrequency("Hour", "yyyyMMddHH", TimeSpan.FromHours(1));

    public string Name { get; }
    public string Format { get; }
    public TimeSpan Interval { get; }

    RollingFrequency(string name, string format, TimeSpan interval)
    {
        if (name == null) throw new ArgumentNullException(nameof(name));
        Format = format ?? throw new ArgumentNullException(nameof(format));
        Name = "{" + name + "}";
        Interval = interval;
    }

    public DateTime GetCurrentCheckpoint(DateTime instant)
    {
        if (this == Hour)
        {
            return instant.Date.AddHours(instant.Hour);
        }
        return instant.Date;
    }

    public DateTime GetNextCheckpoint(DateTime instant) => GetCurrentCheckpoint(instant).Add(Interval);

    public static bool TryGetRollingFrequency(string pathTemplate, out RollingFrequency specifier)
    {
        if (pathTemplate == null) throw new ArgumentNullException(nameof(pathTemplate));
        var frequencies = new[] { Date, Hour }.Where(s => pathTemplate.Contains(s.Name)).ToArray();
        specifier = frequencies.LastOrDefault();
        return specifier != null;
    }
}

再看一下 RollingFileWriter：

public class RollingFileWriter : IMessageWriter, IDisposable
{
    ...

    public RollingFileWriter(string pathFormat, long? fileSizeLimitBytes = null, int? retainedFileCountLimit = null)
    {
        ...
    }

    public Task WriteMessagesAsync(string message, CancellationToken cancellationToken)
    {
        AlignFileWriter();
        return _currentFileWriter.WriteMessagesAsync(message, cancellationToken);
    }

    private void AlignFileWriter()
    {
        DateTime now = DateTime.Now;
        if (!_nextCheckpoint.HasValue)
        {
            OpenFileWriter(now);
        }
        else if (now >= _nextCheckpoint.Value)
        {
            CloseFileWriter();
            OpenFileWriter(now);
        }
    }

    private void OpenFileWriter(DateTime now)
    {
        var currentCheckpoint = _roller.GetCurrentCheckpoint(now);
        _nextCheckpoint = _roller.GetNextCheckpoint(now);

        var existingFiles = Enumerable.Empty<string>();
        try
        {
            existingFiles = Directory.GetFiles(_roller.LogFileDirectory, _roller.FileSearchPattern).Select(Path.GetFileName);
        }
        catch (DirectoryNotFoundException) { }

        var latestForThisCheckpoint = _roller
            .SelectMatches(existingFiles)
            .Where(m => m.DateTime == currentCheckpoint)
            .OrderByDescending(m => m.SequenceNumber)
            .FirstOrDefault();

        var sequence = latestForThisCheckpoint != null ? latestForThisCheckpoint.SequenceNumber : 0;

        const int maxAttempts = 3;
        for (var attempt = 0; attempt < maxAttempts; attempt++)
        {
            string path = _roller.GetLogFilePath(now, sequence);
            try
            {
                _currentFileWriter = new FileWriter(path, _maxfileSizeLimit);
            }
            catch (IOException)
            {
                sequence++;
                continue;
            }
            RollFiles(path);
            return;
        }
    }

    // 刪除超出保留文件數的日志文件
    private void RollFiles(string currentFilePath)
    {
        if (_maxRetainedFiles > 0)
        {
            var potentialMatches = Directory.GetFiles(_roller.LogFileDirectory, _roller.FileSearchPattern)
                .Select(Path.GetFileName);
            var moveFiles = _roller
                .SelectMatches(potentialMatches)
                .OrderByDescending(m => m.DateTime)
                .ThenByDescending(m => m.SequenceNumber)
                .Skip(_maxRetainedFiles.Value)
                .Select(m => m.Filename);
            foreach (var obsolete in moveFiles)
            {
                System.IO.File.Delete(Path.Combine(_roller.LogFileDirectory, obsolete));
            }
        }
    }

    ...
}

根據滾動頻率指定應該創建的文件名，然后調用 FileWriter 進行寫入，具體代碼可以去看文末貼的 GitHub 地址。

FileLogger

FileLogger 則是由上一章講到的 Logger 來調用的，而在這里，它的作用是首先對日志進行過濾，然后將日志組裝成字符串，再調用我們前面定義的 IMessageWriter 進行日志的寫入：

public class FileLogger : ILogger, IDisposable
{
    ...

    public FileLogger(IMessageWriter writer, string category, Func<string, LogLevel, bool> filter)
    {
        ...
    }

    public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
    {
        if (!IsEnabled(logLevel))
        {
            return;
        }
        if (formatter == null)
        {
            throw new ArgumentNullException(nameof(formatter));
        }
        var builder = new StringBuilder();
        builder.Append(DateTimeOffset.Now.ToString("yyyy-MM-dd HH:mm:ss.fff zzz"));
        builder.Append(" [");
        builder.Append(GetLogLevelString(logLevel));
        builder.Append("] ");
        builder.Append(_category);
        builder.Append("[");
        builder.Append(eventId);
        builder.Append("]");
        builder.Append(": ");
        builder.AppendLine(formatter(state, exception));
        if (exception != null)
        {
            builder.AppendLine(exception.ToString());
        }
        _writer.WriteMessagesAsync(builder.ToString()).Wait();
    }

    ...
}

在這里，日志的拼裝是寫死的，后續可以提供一個可配置的日志渲染器，來自定義輸出格式。

ConsoleLoggerProvider

FileLoggerProvider 的唯一職責就是創建 FileLogger：

[ProviderAlias("File")]
public class FileLoggerProvider : ILoggerProvider
{
    ...

    public FileLoggerProvider(IOptionsMonitor<FileLoggerOptions> options)
    {
        _optionsChangeToken = options.OnChange(UpdateOptions);
        UpdateOptions(options.CurrentValue);
    }

    private void UpdateOptions(FileLoggerOptions options)
    {
        if (RollingFrequency.TryGetRollingFrequency(options.Path, out var r))
        {
            _msgWriter = new RollingFileWriter(options.Path, options.FileSizeLimit, options.RetainedFileCountLimit);
        }
        else
        {
            _msgWriter = new FileWriter(options.Path, options.FileSizeLimit);
        }
        if (options.IsEnabledBatching)
        {
            _msgWriter = new BatchingWriter(_msgWriter, options.FlushPeriod, options.BatchSize, options.BackgroundQueueSize);
        }
    }

    public ILogger CreateLogger(string categoryName)
    {
        return new FileLogger(_msgWriter, categoryName, _filter);
    }

    ...
}

首先是 ProviderAlias 特性，為 Provider 指定一個別名，這樣，我們在配置文件中指定 Provider 時，使用別名即可，然后使用了 IOptionsMonitor 模式，監控配置的變化，並進行更新，而不用去重啟Web服務器。

FileLoggerFactoryExtensions

最后便是提供擴展方法，方便我們在 Program 中對日志系統進行配置。而擴展方法的實現只是很簡單的將我們定義的 FileProvider 注入進去：

public static class FileLoggerFactoryExtensions
{
    ...

    public static ILoggingBuilder AddFile(this ILoggingBuilder builder, IConfiguration configuration)
    {
        builder.Services.AddSingleton<IOptionsChangeTokenSource<LoggerFilterOptions>>(new ConfigurationChangeTokenSource<LoggerFilterOptions>(configuration));
        builder.Services.Configure<FileLoggerOptions>(configuration);
        builder.Services.AddSingleton<IConfigureOptions<FileLoggerOptions>>(new FileLoggerConfigureOptions(configuration));
        builder.AddFile();
        return builder;
    }

    ...
}

只提供了 ILoggingBuilder 的擴展，而不再提供 ILoggerFactory 的擴展方法，全力擁抱 .NET Core 2.0。

總結

通過對網上各種流行的開源日志框架學習借鑒，寫了一個 ASP.NET Core 的 Logging 系統的文件擴展，還有很多不足之處，但更多的是一種探索，學習，借此也對 Logging 系統更加了解。而后續會再研究一下分布式日記系統。

最后附上本文所示代碼地址：zero-logging。