From b5e0534777c2d70052aaa2d87b0ed54ed53b64c3 Mon Sep 17 00:00:00 2001 From: Nicholas Blumhardt Date: Fri, 4 Nov 2016 09:54:27 +1000 Subject: [PATCH] Fixes #41 - level switch behaviour when server sends no level --- sample/Sample/Program.cs | 2 +- .../Sinks/Seq/ControlledLevelSwitch.cs | 73 +++++++++++++++ .../Sinks/Seq/DurableSeqSink.cs | 4 +- .../Sinks/Seq/HttpLogShipper.cs | 51 ++--------- src/Serilog.Sinks.Seq/Sinks/Seq/SeqSink.cs | 42 +++------ .../ControlledLevelSwitchTests.cs | 90 +++++++++++++++++++ test/Serilog.Sinks.Seq.Tests/Support/Some.cs | 22 ++++- 7 files changed, 206 insertions(+), 78 deletions(-) create mode 100644 src/Serilog.Sinks.Seq/Sinks/Seq/ControlledLevelSwitch.cs create mode 100644 test/Serilog.Sinks.Seq.Tests/ControlledLevelSwitchTests.cs diff --git a/sample/Sample/Program.cs b/sample/Sample/Program.cs index d350a91..47fb0ae 100644 --- a/sample/Sample/Program.cs +++ b/sample/Sample/Program.cs @@ -23,7 +23,7 @@ public static void Main(string[] args) Log.Information("Sample starting up"); - foreach (var i in Enumerable.Range(0, 1000)) + foreach (var i in Enumerable.Range(0, 10)) { Log.Information("Running loop {Counter}", i); diff --git a/src/Serilog.Sinks.Seq/Sinks/Seq/ControlledLevelSwitch.cs b/src/Serilog.Sinks.Seq/Sinks/Seq/ControlledLevelSwitch.cs new file mode 100644 index 0000000..6d942b1 --- /dev/null +++ b/src/Serilog.Sinks.Seq/Sinks/Seq/ControlledLevelSwitch.cs @@ -0,0 +1,73 @@ +// Serilog.Sinks.Seq Copyright 2016 Serilog Contributors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +using System; +using Serilog.Core; +using Serilog.Events; + +namespace Serilog.Sinks.Seq +{ + /// + /// Instances of this type are single-threaded, generally only updated on a background + /// timer thread. An exception is , which may be called + /// concurrently but performs no synchronization. + /// + class ControlledLevelSwitch + { + // If non-null, then background level checks will be performed; set either through the constructor + // or in response to a level specification from the server. Never set to null after being made non-null. + LoggingLevelSwitch _controlledSwitch; + LogEventLevel? _originalLevel; + + public ControlledLevelSwitch(LoggingLevelSwitch controlledSwitch = null) + { + _controlledSwitch = controlledSwitch; + } + + public bool IsActive => _controlledSwitch != null; + + public bool IsIncluded(LogEvent evt) + { + // Concurrent, but not synchronized. + var controlledSwitch = _controlledSwitch; + return controlledSwitch == null || + (int)controlledSwitch.MinimumLevel <= (int)evt.Level; + } + + public void Update(LogEventLevel? minimumAcceptedLevel) + { + if (minimumAcceptedLevel == null) + { + if (_controlledSwitch != null && _originalLevel.HasValue) + _controlledSwitch.MinimumLevel = _originalLevel.Value; + + return; + } + + if (_controlledSwitch == null) + { + // The server is controlling the logging level, but not the overall logger. Hence, if the server + // stops controlling the level, the switch should become transparent. + _originalLevel = LevelAlias.Minimum; + _controlledSwitch = new LoggingLevelSwitch(minimumAcceptedLevel.Value); + return; + } + + if (!_originalLevel.HasValue) + _originalLevel = _controlledSwitch.MinimumLevel; + + _controlledSwitch.MinimumLevel = minimumAcceptedLevel.Value; + } + } +} diff --git a/src/Serilog.Sinks.Seq/Sinks/Seq/DurableSeqSink.cs b/src/Serilog.Sinks.Seq/Sinks/Seq/DurableSeqSink.cs index 1359fdc..f63ec14 100644 --- a/src/Serilog.Sinks.Seq/Sinks/Seq/DurableSeqSink.cs +++ b/src/Serilog.Sinks.Seq/Sinks/Seq/DurableSeqSink.cs @@ -72,9 +72,7 @@ public void Emit(LogEvent logEvent) { // This is a lagging indicator, but the network bandwidth usage benefits // are worth the ambiguity. - var minimumAcceptedLevel = _shipper.MinimumAcceptedLevel; - if (minimumAcceptedLevel == null || - (int)minimumAcceptedLevel <= (int)logEvent.Level) + if (_shipper.IsIncluded(logEvent)) { _sink.Emit(logEvent); } diff --git a/src/Serilog.Sinks.Seq/Sinks/Seq/HttpLogShipper.cs b/src/Serilog.Sinks.Seq/Sinks/Seq/HttpLogShipper.cs index 1aca9e0..49b5c7f 100644 --- a/src/Serilog.Sinks.Seq/Sinks/Seq/HttpLogShipper.cs +++ b/src/Serilog.Sinks.Seq/Sinks/Seq/HttpLogShipper.cs @@ -50,7 +50,7 @@ class HttpLogShipper : IDisposable readonly object _stateLock = new object(); readonly PortableTimer _timer; - LoggingLevelSwitch _levelControlSwitch; + ControlledLevelSwitch _controlledSwitch; DateTime _nextRequiredLevelCheckUtc = DateTime.UtcNow.Add(RequiredLevelCheckInterval); volatile bool _unloading; @@ -68,7 +68,7 @@ public HttpLogShipper( _apiKey = apiKey; _batchPostingLimit = batchPostingLimit; _eventBodyLimitBytes = eventBodyLimitBytes; - _levelControlSwitch = levelControlSwitch; + _controlledSwitch = new ControlledLevelSwitch(levelControlSwitch); _connectionSchedule = new ExponentialBackoffConnectionSchedule(period); _retainedInvalidPayloadsLimitBytes = retainedInvalidPayloadsLimitBytes; _httpClient = messageHandler != null ? @@ -100,35 +100,14 @@ void CloseAndFlush() OnTick().ConfigureAwait(false).GetAwaiter().GetResult(); } - /// - /// Get the last "minimum level" indicated by the Seq server, if any. - /// - public LogEventLevel? MinimumAcceptedLevel + public bool IsIncluded(LogEvent logEvent) { - get - { - lock (_stateLock) - return _levelControlSwitch?.MinimumLevel; - } + return _controlledSwitch.IsIncluded(logEvent); } - /// - /// Performs application-defined tasks associated with freeing, releasing, or resetting unmanaged resources. - /// - /// 2 + /// public void Dispose() { - Dispose(true); - } - - /// - /// Free resources held by the sink. - /// - /// If true, called because the object is being disposed; if false, - /// the object is being disposed from the finalizer. - protected virtual void Dispose(bool disposing) - { - if (!disposing) return; CloseAndFlush(); } @@ -172,7 +151,7 @@ async Task OnTick() var payload = ReadPayload(currentFile, ref nextLineBeginsAtOffset, ref count); - if (count > 0 || _levelControlSwitch != null && _nextRequiredLevelCheckUtc < DateTime.UtcNow) + if (count > 0 || _controlledSwitch.IsActive && _nextRequiredLevelCheckUtc < DateTime.UtcNow) { lock (_stateLock) { @@ -244,7 +223,7 @@ async Task OnTick() { lock (_stateLock) { - UpdateLevelControlSwitch(minimumAcceptedLevel); + _controlledSwitch.Update(minimumAcceptedLevel); if (!_unloading) SetTimer(); @@ -315,22 +294,6 @@ orderby candiateFileInfo.LastAccessTimeUtc descending } } - void UpdateLevelControlSwitch(LogEventLevel? minimumAcceptedLevel) - { - if (minimumAcceptedLevel == null) - { - if (_levelControlSwitch != null) - _levelControlSwitch.MinimumLevel = LevelAlias.Minimum; - } - else - { - if (_levelControlSwitch == null) - _levelControlSwitch = new LoggingLevelSwitch(minimumAcceptedLevel.Value); - else - _levelControlSwitch.MinimumLevel = minimumAcceptedLevel.Value; - } - } - string ReadPayload(string currentFile, ref long nextLineBeginsAtOffset, ref int count) { var payload = new StringWriter(); diff --git a/src/Serilog.Sinks.Seq/Sinks/Seq/SeqSink.cs b/src/Serilog.Sinks.Seq/Sinks/Seq/SeqSink.cs index e861468..0c92eae 100644 --- a/src/Serilog.Sinks.Seq/Sinks/Seq/SeqSink.cs +++ b/src/Serilog.Sinks.Seq/Sinks/Seq/SeqSink.cs @@ -30,22 +30,20 @@ namespace Serilog.Sinks.Seq { class SeqSink : PeriodicBatchingSink { - readonly string _apiKey; - readonly long? _eventBodyLimitBytes; - readonly HttpClient _httpClient; + public const int DefaultBatchPostingLimit = 1000; + public static readonly TimeSpan DefaultPeriod = TimeSpan.FromSeconds(2); + public const int DefaultQueueSizeLimit = 100000; + static readonly TimeSpan RequiredLevelCheckInterval = TimeSpan.FromMinutes(2); static readonly JsonValueFormatter JsonValueFormatter = new JsonValueFormatter(); - // If non-null, then background level checks will be performed; set either through the constructor - // or in response to a level specification from the server. Never set to null after being made non-null. - LoggingLevelSwitch _levelControlSwitch; + readonly string _apiKey; + readonly long? _eventBodyLimitBytes; + readonly HttpClient _httpClient; readonly bool _useCompactFormat; - static readonly TimeSpan RequiredLevelCheckInterval = TimeSpan.FromMinutes(2); - DateTime _nextRequiredLevelCheckUtc = DateTime.UtcNow.Add(RequiredLevelCheckInterval); - public const int DefaultBatchPostingLimit = 1000; - public static readonly TimeSpan DefaultPeriod = TimeSpan.FromSeconds(2); - public const int DefaultQueueSizeLimit = 100000; + DateTime _nextRequiredLevelCheckUtc = DateTime.UtcNow.Add(RequiredLevelCheckInterval); + ControlledLevelSwitch _controlledSwitch; public SeqSink( string serverUrl, @@ -62,7 +60,7 @@ public SeqSink( if (serverUrl == null) throw new ArgumentNullException(nameof(serverUrl)); _apiKey = apiKey; _eventBodyLimitBytes = eventBodyLimitBytes; - _levelControlSwitch = levelControlSwitch; + _controlledSwitch = new ControlledLevelSwitch(levelControlSwitch); _useCompactFormat = useCompactFormat; _httpClient = messageHandler != null ? new HttpClient(messageHandler) : new HttpClient(); _httpClient.BaseAddress = new Uri(SeqApi.NormalizeServerBaseAddress(serverUrl)); @@ -80,7 +78,7 @@ protected override void Dispose(bool disposing) // configured to set a specific level, before background level checks will be performed. protected override void OnEmptyBatch() { - if (_levelControlSwitch != null && + if (_controlledSwitch.IsActive && _nextRequiredLevelCheckUtc < DateTime.UtcNow) { EmitBatch(Enumerable.Empty()); @@ -112,19 +110,7 @@ protected override async Task EmitBatchAsync(IEnumerable events) throw new LoggingFailedException($"Received failed result {result.StatusCode} when posting events to Seq"); var returned = await result.Content.ReadAsStringAsync(); - var minimumAcceptedLevel = SeqApi.ReadEventInputResult(returned); - if (minimumAcceptedLevel == null) - { - if (_levelControlSwitch != null) - _levelControlSwitch.MinimumLevel = LevelAlias.Minimum; - } - else - { - if (_levelControlSwitch == null) - _levelControlSwitch = new LoggingLevelSwitch(minimumAcceptedLevel.Value); - else - _levelControlSwitch.MinimumLevel = minimumAcceptedLevel.Value; - } + _controlledSwitch.Update(SeqApi.ReadEventInputResult(returned)); } internal static string FormatCompactPayload(IEnumerable events, long? eventBodyLimitBytes) @@ -190,9 +176,7 @@ internal static string FormatRawPayload(IEnumerable events, long? even protected override bool CanInclude(LogEvent evt) { - var levelControlSwitch = _levelControlSwitch; - return levelControlSwitch == null || - (int)levelControlSwitch.MinimumLevel <= (int)evt.Level; + return _controlledSwitch.IsIncluded(evt); } static bool CheckEventBodySize(string json, long? eventBodyLimitBytes) diff --git a/test/Serilog.Sinks.Seq.Tests/ControlledLevelSwitchTests.cs b/test/Serilog.Sinks.Seq.Tests/ControlledLevelSwitchTests.cs new file mode 100644 index 0000000..72803d9 --- /dev/null +++ b/test/Serilog.Sinks.Seq.Tests/ControlledLevelSwitchTests.cs @@ -0,0 +1,90 @@ +using Serilog.Core; +using Serilog.Events; +using Serilog.Sinks.Seq.Tests.Support; +using Xunit; + +namespace Serilog.Sinks.Seq.Tests +{ + public class ControlledLevelSwitchTests + { + [Fact] + public void WhenTheServerSendsALevelTheSwitchIsAdjusted() + { + var lls = new LoggingLevelSwitch(LogEventLevel.Warning); + var cls = new ControlledLevelSwitch(lls); + cls.Update(LogEventLevel.Debug); + Assert.Equal(LogEventLevel.Debug, lls.MinimumLevel); + } + + [Fact] + public void WhenTheServerSendsNoLevelTheSwitchIsNotInitiallyAdjusted() + { + var lls = new LoggingLevelSwitch(LogEventLevel.Warning); + lls.MinimumLevel = LogEventLevel.Fatal; + var cls = new ControlledLevelSwitch(lls); + cls.Update(null); + Assert.Equal(LogEventLevel.Fatal, lls.MinimumLevel); + } + + [Fact] + public void WhenTheServerSendsNoLevelTheSwitchIsResetIfPreviouslyAdjusted() + { + var lls = new LoggingLevelSwitch(LogEventLevel.Warning); + var cls = new ControlledLevelSwitch(lls); + cls.Update(LogEventLevel.Information); + cls.Update(null); + Assert.Equal(LogEventLevel.Warning, lls.MinimumLevel); + } + + [Fact] + public void WithNoSwitchToControlAllEventsAreIncluded() + { + var cls = new ControlledLevelSwitch(null); + Assert.True(cls.IsIncluded(Some.DebugEvent())); + } + + [Fact] + public void WithNoSwitchToControlEventsAreStillFiltered() + { + var cls = new ControlledLevelSwitch(null); + cls.Update(LogEventLevel.Warning); + Assert.True(cls.IsIncluded(Some.ErrorEvent())); + Assert.False(cls.IsIncluded(Some.InformationEvent())); + } + + [Fact] + public void WithNoSwitchToControlAllEventsAreIncludedAfterReset() + { + var cls = new ControlledLevelSwitch(null); + cls.Update(LogEventLevel.Warning); + cls.Update(null); + Assert.True(cls.IsIncluded(Some.DebugEvent())); + } + + [Fact] + public void WhenControllingASwitchTheControllerIsActive() + { + var cls = new ControlledLevelSwitch(new LoggingLevelSwitch()); + Assert.True(cls.IsActive); + } + + [Fact] + public void WhenNotControllingASwitchTheControllerIsNotActive() + { + var cls = new ControlledLevelSwitch(); + Assert.False(cls.IsActive); + } + + [Fact] + public void AfterServerControlhTheControllerIsAlwaysActive() + { + var cls = new ControlledLevelSwitch(); + + cls.Update(LogEventLevel.Information); + Assert.True(cls.IsActive); + + cls.Update(null); + Assert.True(cls.IsActive); + } + } +} diff --git a/test/Serilog.Sinks.Seq.Tests/Support/Some.cs b/test/Serilog.Sinks.Seq.Tests/Support/Some.cs index 97f258e..8b44714 100644 --- a/test/Serilog.Sinks.Seq.Tests/Support/Some.cs +++ b/test/Serilog.Sinks.Seq.Tests/Support/Some.cs @@ -13,6 +13,11 @@ public static LogEvent LogEvent(string messageTemplate, params object[] property } public static LogEvent LogEvent(Exception exception, string messageTemplate, params object[] propertyValues) + { + return LogEvent(LogEventLevel.Information, exception, messageTemplate, propertyValues); + } + + public static LogEvent LogEvent(LogEventLevel level, Exception exception, string messageTemplate, params object[] propertyValues) { var log = new LoggerConfiguration().CreateLogger(); MessageTemplate template; @@ -23,7 +28,22 @@ public static LogEvent LogEvent(Exception exception, string messageTemplate, par { throw new XunitException("Template could not be bound."); } - return new LogEvent(DateTimeOffset.Now, LogEventLevel.Information, exception, template, properties); + return new LogEvent(DateTimeOffset.Now, level, exception, template, properties); + } + + public static LogEvent DebugEvent() + { + return LogEvent(LogEventLevel.Debug, null, "Debug event"); + } + + public static LogEvent InformationEvent() + { + return LogEvent(LogEventLevel.Information, null, "Information event"); + } + + public static LogEvent ErrorEvent() + { + return LogEvent(LogEventLevel.Error, null, "Error event"); } } }