Skip to content

Commit

Permalink
Merge pull request #43 from nblumhardt/dev
Browse files Browse the repository at this point in the history
Fixes #41 - level switch behaviour when server sends no level
  • Loading branch information
nblumhardt authored Nov 3, 2016
2 parents cd8b401 + b5e0534 commit 8181d26
Show file tree
Hide file tree
Showing 7 changed files with 206 additions and 78 deletions.
2 changes: 1 addition & 1 deletion sample/Sample/Program.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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);

Expand Down
73 changes: 73 additions & 0 deletions src/Serilog.Sinks.Seq/Sinks/Seq/ControlledLevelSwitch.cs
Original file line number Diff line number Diff line change
@@ -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
{
/// <summary>
/// Instances of this type are single-threaded, generally only updated on a background
/// timer thread. An exception is <see cref="IsIncluded(LogEvent)"/>, which may be called
/// concurrently but performs no synchronization.
/// </summary>
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;
}
}
}
4 changes: 1 addition & 3 deletions src/Serilog.Sinks.Seq/Sinks/Seq/DurableSeqSink.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
Expand Down
51 changes: 7 additions & 44 deletions src/Serilog.Sinks.Seq/Sinks/Seq/HttpLogShipper.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand All @@ -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 ?
Expand Down Expand Up @@ -100,35 +100,14 @@ void CloseAndFlush()
OnTick().ConfigureAwait(false).GetAwaiter().GetResult();
}

/// <summary>
/// Get the last "minimum level" indicated by the Seq server, if any.
/// </summary>
public LogEventLevel? MinimumAcceptedLevel
public bool IsIncluded(LogEvent logEvent)
{
get
{
lock (_stateLock)
return _levelControlSwitch?.MinimumLevel;
}
return _controlledSwitch.IsIncluded(logEvent);
}

/// <summary>
/// Performs application-defined tasks associated with freeing, releasing, or resetting unmanaged resources.
/// </summary>
/// <filterpriority>2</filterpriority>
/// <inheritdoc/>
public void Dispose()
{
Dispose(true);
}

/// <summary>
/// Free resources held by the sink.
/// </summary>
/// <param name="disposing">If true, called because the object is being disposed; if false,
/// the object is being disposed from the finalizer.</param>
protected virtual void Dispose(bool disposing)
{
if (!disposing) return;
CloseAndFlush();
}

Expand Down Expand Up @@ -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)
{
Expand Down Expand Up @@ -244,7 +223,7 @@ async Task OnTick()
{
lock (_stateLock)
{
UpdateLevelControlSwitch(minimumAcceptedLevel);
_controlledSwitch.Update(minimumAcceptedLevel);

if (!_unloading)
SetTimer();
Expand Down Expand Up @@ -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();
Expand Down
42 changes: 13 additions & 29 deletions src/Serilog.Sinks.Seq/Sinks/Seq/SeqSink.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand All @@ -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));
Expand All @@ -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<LogEvent>());
Expand Down Expand Up @@ -112,19 +110,7 @@ protected override async Task EmitBatchAsync(IEnumerable<LogEvent> 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<LogEvent> events, long? eventBodyLimitBytes)
Expand Down Expand Up @@ -190,9 +176,7 @@ internal static string FormatRawPayload(IEnumerable<LogEvent> 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)
Expand Down
90 changes: 90 additions & 0 deletions test/Serilog.Sinks.Seq.Tests/ControlledLevelSwitchTests.cs
Original file line number Diff line number Diff line change
@@ -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);
}
}
}
Loading

0 comments on commit 8181d26

Please sign in to comment.