From df4829ba23775adb1dacb069d2d0890de195740b Mon Sep 17 00:00:00 2001 From: "Mattias Kindborg @FantasticFiasco" Date: Wed, 31 Jan 2018 08:01:12 +0100 Subject: [PATCH] feat: add event formatter called NamespacedTextFormatter (#45) Add event formatter called `NamespacedTextFormatter` suited for a micro-service architecture where log events are sent to the Elastic Stack. The event formatter reduces the risk of two services logging properties with identical names but with different types, which the Elastic Stack doesn't support. Closes #39 --- CHANGELOG.md | 4 + serilog-sinks-http.sln.DotSettings | 9 + .../LoggerSinkConfigurationExtensions.cs | 6 +- .../BatchFormatters/ArrayBatchFormatter.cs | 6 +- .../Http/BatchFormatters/BatchFormatter.cs | 6 +- .../BatchFormatters/DefaultBatchFormatter.cs | 8 +- .../Http/Private/Network/HttpLogShipper.cs | 11 +- .../Sinks/Http/Private/Sinks/HttpSink.cs | 2 + .../ExponentialBackoffConnectionSchedule.cs | 3 +- .../Sinks/Http/Private/Time/PortableTimer.cs | 10 +- .../CompactRenderedTextFormatter.cs | 1 + .../TextFormatters/CompactTextFormatter.cs | 7 +- .../TextFormatters/NamespacedTextFormatter.cs | 259 ++++++++++ .../NormalRenderedTextFormatter.cs | 1 + .../TextFormatters/NormalTextFormatter.cs | 7 +- .../Controllers/Dto/CompactEventDto.cs | 26 - .../Controllers/Dto/RenderingDto.cs | 4 +- .../CompactTextFormatterTest.cs | 153 +++--- .../NamespacedTextFormatterTest.cs | 457 ++++++++++++++++++ .../TextFormatters/NormalTextFormatterTest.cs | 180 ++++--- 20 files changed, 952 insertions(+), 208 deletions(-) create mode 100644 src/Serilog.Sinks.Http/Sinks/Http/TextFormatters/NamespacedTextFormatter.cs delete mode 100644 test/Serilog.Sinks.Http.LogServer/Controllers/Dto/CompactEventDto.cs create mode 100644 test/Serilog.Sinks.HttpTests/Sinks/Http/TextFormatters/NamespacedTextFormatterTest.cs diff --git a/CHANGELOG.md b/CHANGELOG.md index e1fe4a23..2bfe44c8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,10 @@ This project adheres to [Semantic Versioning](http://semver.org/) and is followi ## Unreleased +### Added + +- Event formatter called `NamespacedTextFormatter` suited for a micro-service architecture where log events are sent to the Elastic Stack. The event formatter reduces the risk of two services logging properties with identical names but with different types, which the Elastic Stack doesn't support. + ### Removed - Support for .NET Standard 2.0 since the sink also has support for .NET Standard 1.3 diff --git a/serilog-sinks-http.sln.DotSettings b/serilog-sinks-http.sln.DotSettings index 21fae1b0..7527d4ec 100644 --- a/serilog-sinks-http.sln.DotSettings +++ b/serilog-sinks-http.sln.DotSettings @@ -90,8 +90,12 @@ NEXT_LINE 1 1 + False + NEVER False False + NEVER + NEVER False False LINE_BREAK @@ -133,7 +137,12 @@ <Policy Inspect="True" Prefix="T" Suffix="" Style="AaBb" /> <Policy Inspect="True" Prefix="" Suffix="" Style="AaBb" /> <Policy Inspect="True" Prefix="" Suffix="" Style="aaBb" /> + True + True + True + True True + True True True True diff --git a/src/Serilog.Sinks.Http/LoggerSinkConfigurationExtensions.cs b/src/Serilog.Sinks.Http/LoggerSinkConfigurationExtensions.cs index 680983e3..3d2132e2 100644 --- a/src/Serilog.Sinks.Http/LoggerSinkConfigurationExtensions.cs +++ b/src/Serilog.Sinks.Http/LoggerSinkConfigurationExtensions.cs @@ -70,8 +70,7 @@ public static LoggerConfiguration Http( LogEventLevel restrictedToMinimumLevel = LevelAlias.Minimum, IHttpClient httpClient = null) { - if (sinkConfiguration == null) - throw new ArgumentNullException(nameof(sinkConfiguration)); + if (sinkConfiguration == null) throw new ArgumentNullException(nameof(sinkConfiguration)); var sink = new HttpSink( requestUri, @@ -143,8 +142,7 @@ public static LoggerConfiguration DurableHttp( LogEventLevel restrictedToMinimumLevel = LevelAlias.Minimum, IHttpClient httpClient = null) { - if (sinkConfiguration == null) - throw new ArgumentNullException(nameof(sinkConfiguration)); + if (sinkConfiguration == null) throw new ArgumentNullException(nameof(sinkConfiguration)); var sink = new DurableHttpSink( requestUri, diff --git a/src/Serilog.Sinks.Http/Sinks/Http/BatchFormatters/ArrayBatchFormatter.cs b/src/Serilog.Sinks.Http/Sinks/Http/BatchFormatters/ArrayBatchFormatter.cs index 6f1697b4..d9cf878e 100644 --- a/src/Serilog.Sinks.Http/Sinks/Http/BatchFormatters/ArrayBatchFormatter.cs +++ b/src/Serilog.Sinks.Http/Sinks/Http/BatchFormatters/ArrayBatchFormatter.cs @@ -54,10 +54,8 @@ public ArrayBatchFormatter(long? eventBodyLimitBytes = 256 * 1024) /// public override void Format(IEnumerable logEvents, TextWriter output) { - if (logEvents == null) - throw new ArgumentNullException(nameof(logEvents)); - if (output == null) - throw new ArgumentNullException(nameof(output)); + if (logEvents == null) throw new ArgumentNullException(nameof(logEvents)); + if (output == null) throw new ArgumentNullException(nameof(output)); // Abort if sequence of log events is empty if (!logEvents.Any()) diff --git a/src/Serilog.Sinks.Http/Sinks/Http/BatchFormatters/BatchFormatter.cs b/src/Serilog.Sinks.Http/Sinks/Http/BatchFormatters/BatchFormatter.cs index 2f97027d..1d638cad 100644 --- a/src/Serilog.Sinks.Http/Sinks/Http/BatchFormatters/BatchFormatter.cs +++ b/src/Serilog.Sinks.Http/Sinks/Http/BatchFormatters/BatchFormatter.cs @@ -56,10 +56,8 @@ protected BatchFormatter(long? eventBodyLimitBytes) /// public void Format(IEnumerable logEvents, ITextFormatter formatter, TextWriter output) { - if (logEvents == null) - throw new ArgumentNullException(nameof(logEvents)); - if (formatter == null) - throw new ArgumentNullException(nameof(formatter)); + if (logEvents == null) throw new ArgumentNullException(nameof(logEvents)); + if (formatter == null) throw new ArgumentNullException(nameof(formatter)); IEnumerable formattedLogEvents = logEvents.Select( logEvent => diff --git a/src/Serilog.Sinks.Http/Sinks/Http/BatchFormatters/DefaultBatchFormatter.cs b/src/Serilog.Sinks.Http/Sinks/Http/BatchFormatters/DefaultBatchFormatter.cs index f5b17aac..5f3f9e33 100644 --- a/src/Serilog.Sinks.Http/Sinks/Http/BatchFormatters/DefaultBatchFormatter.cs +++ b/src/Serilog.Sinks.Http/Sinks/Http/BatchFormatters/DefaultBatchFormatter.cs @@ -20,7 +20,7 @@ namespace Serilog.Sinks.Http.BatchFormatters { /// - /// Formatter serializing batches of log events into a JSON object under a property called 'events'. + /// Formatter serializing batches of log events into a JSON object under a property called "events". /// /// Example: /// { @@ -56,10 +56,8 @@ public DefaultBatchFormatter(long? eventBodyLimitBytes = 256 * 1024) /// public override void Format(IEnumerable logEvents, TextWriter output) { - if (logEvents == null) - throw new ArgumentNullException(nameof(logEvents)); - if (output == null) - throw new ArgumentNullException(nameof(output)); + if (logEvents == null) throw new ArgumentNullException(nameof(logEvents)); + if (output == null) throw new ArgumentNullException(nameof(output)); // Abort if sequence of log events is empty if (!logEvents.Any()) diff --git a/src/Serilog.Sinks.Http/Sinks/Http/Private/Network/HttpLogShipper.cs b/src/Serilog.Sinks.Http/Sinks/Http/Private/Network/HttpLogShipper.cs index 50674d36..27e85436 100644 --- a/src/Serilog.Sinks.Http/Sinks/Http/Private/Network/HttpLogShipper.cs +++ b/src/Serilog.Sinks.Http/Sinks/Http/Private/Network/HttpLogShipper.cs @@ -57,12 +57,9 @@ public HttpLogShipper( TimeSpan period, IBatchFormatter batchFormatter) { - if (bufferPathFormat == null) - throw new ArgumentNullException(nameof(bufferPathFormat)); - if (bufferPathFormat != bufferPathFormat.Trim()) - throw new ArgumentException("bufferPathFormat must not contain any leading or trailing whitespaces", nameof(bufferPathFormat)); - if (batchPostingLimit <= 0) - throw new ArgumentException("batchPostingLimit must be 1 or greater", nameof(batchPostingLimit)); + if (bufferPathFormat == null) throw new ArgumentNullException(nameof(bufferPathFormat)); + if (bufferPathFormat != bufferPathFormat.Trim()) throw new ArgumentException("bufferPathFormat must not contain any leading or trailing whitespaces", nameof(bufferPathFormat)); + if (batchPostingLimit <= 0) throw new ArgumentException("batchPostingLimit must be 1 or greater", nameof(batchPostingLimit)); this.client = client ?? throw new ArgumentNullException(nameof(client)); this.requestUri = requestUri ?? throw new ArgumentNullException(nameof(requestUri)); @@ -146,7 +143,7 @@ private async Task OnTick() } if (string.IsNullOrEmpty(payload)) - continue;; + continue; var content = new StringContent(payload, Encoding.UTF8, ContentType); diff --git a/src/Serilog.Sinks.Http/Sinks/Http/Private/Sinks/HttpSink.cs b/src/Serilog.Sinks.Http/Sinks/Http/Private/Sinks/HttpSink.cs index 5984a3b2..29bb33a6 100644 --- a/src/Serilog.Sinks.Http/Sinks/Http/Private/Sinks/HttpSink.cs +++ b/src/Serilog.Sinks.Http/Sinks/Http/Private/Sinks/HttpSink.cs @@ -71,7 +71,9 @@ protected override async Task EmitBatchAsync(IEnumerable events) .ConfigureAwait(false); if (!result.IsSuccessStatusCode) + { throw new LoggingFailedException($"Received failed result {result.StatusCode} when posting events to {requestUri}"); + } } /// diff --git a/src/Serilog.Sinks.Http/Sinks/Http/Private/Time/ExponentialBackoffConnectionSchedule.cs b/src/Serilog.Sinks.Http/Sinks/Http/Private/Time/ExponentialBackoffConnectionSchedule.cs index 62c0917a..e5d401f9 100644 --- a/src/Serilog.Sinks.Http/Sinks/Http/Private/Time/ExponentialBackoffConnectionSchedule.cs +++ b/src/Serilog.Sinks.Http/Sinks/Http/Private/Time/ExponentialBackoffConnectionSchedule.cs @@ -27,8 +27,7 @@ internal class ExponentialBackoffConnectionSchedule public ExponentialBackoffConnectionSchedule(TimeSpan period) { - if (period < TimeSpan.Zero) - throw new ArgumentOutOfRangeException(nameof(period), "The connection retry period must be a positive timespan"); + if (period < TimeSpan.Zero) throw new ArgumentOutOfRangeException(nameof(period), "The connection retry period must be a positive timespan"); this.period = period; } diff --git a/src/Serilog.Sinks.Http/Sinks/Http/Private/Time/PortableTimer.cs b/src/Serilog.Sinks.Http/Sinks/Http/Private/Time/PortableTimer.cs index 661d148d..c7f41e9d 100644 --- a/src/Serilog.Sinks.Http/Sinks/Http/Private/Time/PortableTimer.cs +++ b/src/Serilog.Sinks.Http/Sinks/Http/Private/Time/PortableTimer.cs @@ -29,23 +29,21 @@ internal class PortableTimer : IDisposable public PortableTimer(Func onTick) { - if (onTick == null) - throw new ArgumentNullException(nameof(onTick)); - - this.onTick = onTick; + this.onTick = onTick ?? throw new ArgumentNullException(nameof(onTick)); timer = new Timer(_ => OnTick(), null, Timeout.Infinite, Timeout.Infinite); } public void Start(TimeSpan interval) { - if (interval < TimeSpan.Zero) - throw new ArgumentOutOfRangeException(nameof(interval)); + if (interval < TimeSpan.Zero) throw new ArgumentOutOfRangeException(nameof(interval)); lock (stateLock) { if (disposed) + { throw new ObjectDisposedException(nameof(PortableTimer)); + } timer.Change(interval, Timeout.InfiniteTimeSpan); } diff --git a/src/Serilog.Sinks.Http/Sinks/Http/TextFormatters/CompactRenderedTextFormatter.cs b/src/Serilog.Sinks.Http/Sinks/Http/TextFormatters/CompactRenderedTextFormatter.cs index a206f90d..4791b626 100644 --- a/src/Serilog.Sinks.Http/Sinks/Http/TextFormatters/CompactRenderedTextFormatter.cs +++ b/src/Serilog.Sinks.Http/Sinks/Http/TextFormatters/CompactRenderedTextFormatter.cs @@ -24,6 +24,7 @@ namespace Serilog.Sinks.Http.TextFormatters /// /// /// + /// /// public class CompactRenderedTextFormatter : CompactTextFormatter { diff --git a/src/Serilog.Sinks.Http/Sinks/Http/TextFormatters/CompactTextFormatter.cs b/src/Serilog.Sinks.Http/Sinks/Http/TextFormatters/CompactTextFormatter.cs index f2d5d4a9..e0be8e1a 100644 --- a/src/Serilog.Sinks.Http/Sinks/Http/TextFormatters/CompactTextFormatter.cs +++ b/src/Serilog.Sinks.Http/Sinks/Http/TextFormatters/CompactTextFormatter.cs @@ -33,6 +33,7 @@ namespace Serilog.Sinks.Http.TextFormatters /// /// /// + /// /// public class CompactTextFormatter : ITextFormatter { @@ -64,10 +65,8 @@ public void Format(LogEvent logEvent, TextWriter output) private void FormatContent(LogEvent logEvent, TextWriter output) { - if (logEvent == null) - throw new ArgumentNullException(nameof(logEvent)); - if (output == null) - throw new ArgumentNullException(nameof(output)); + if (logEvent == null) throw new ArgumentNullException(nameof(logEvent)); + if (output == null) throw new ArgumentNullException(nameof(output)); output.Write("{\"@t\":\""); output.Write(logEvent.Timestamp.UtcDateTime.ToString("o")); diff --git a/src/Serilog.Sinks.Http/Sinks/Http/TextFormatters/NamespacedTextFormatter.cs b/src/Serilog.Sinks.Http/Sinks/Http/TextFormatters/NamespacedTextFormatter.cs new file mode 100644 index 00000000..0f168275 --- /dev/null +++ b/src/Serilog.Sinks.Http/Sinks/Http/TextFormatters/NamespacedTextFormatter.cs @@ -0,0 +1,259 @@ +// Copyright 2015-2018 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 System.Collections.Generic; +using System.IO; +using System.Linq; +using Serilog.Debugging; +using Serilog.Events; +using Serilog.Formatting; +using Serilog.Formatting.Json; +using Serilog.Parsing; + +namespace Serilog.Sinks.Http.TextFormatters +{ + /// + /// JSON formatter serializing log events into a format where the message properties are placed + /// into their own namespace. It is designed for a micro-service architecture where one wish to + /// reduce the risk of having multiple services sending log events with identical property + /// names but different value types, something that is unsupported by the Elastic Stack. + /// + /// + /// + /// + /// + /// + public abstract class NamespacedTextFormatter : ITextFormatter + { + private readonly string component; + private readonly string subComponent; + + /// + /// Initializes a new instance of the class. + /// + /// + /// The component name, which will be serialized into a sub-property of "Properties" in the + /// JSON document. + /// + /// + /// The sub-component name, which will be serialized into a sub-property of + /// in the JSON document. If value is null it will be omitted + /// from the serialized JSON document, and the message properties will be serialized as + /// properties of . Default value is null. + /// + protected NamespacedTextFormatter(string component, string subComponent = null) + { + this.component = component ?? throw new ArgumentNullException(nameof(component)); + this.subComponent = subComponent; + } + + /// + /// Gets or sets a value indicating whether the message is rendered into JSON. Default + /// value is true. + /// + protected bool IsRenderingMessage { get; set; } = true; + + /// + /// Format the log event into the output. + /// + /// The event to format. + /// The output. + public void Format(LogEvent logEvent, TextWriter output) + { + try + { + var buffer = new StringWriter(); + FormatContent(logEvent, buffer); + + // If formatting was successful, write to output + output.WriteLine(buffer.ToString()); + } + catch (Exception e) + { + LogNonFormattableEvent(logEvent, e); + } + } + + private void FormatContent(LogEvent logEvent, TextWriter output) + { + if (logEvent == null) throw new ArgumentNullException(nameof(logEvent)); + if (output == null) throw new ArgumentNullException(nameof(output)); + + output.Write("{\"Timestamp\":\""); + output.Write(logEvent.Timestamp.ToString("o")); + + output.Write("\",\"Level\":\""); + output.Write(logEvent.Level); + + output.Write("\",\"MessageTemplate\":"); + JsonValueFormatter.WriteQuotedJsonString(logEvent.MessageTemplate.Text, output); + + if (IsRenderingMessage) + { + output.Write(",\"RenderedMessage\":"); + + var message = logEvent.MessageTemplate.Render(logEvent.Properties); + JsonValueFormatter.WriteQuotedJsonString(message, output); + } + + if (logEvent.Exception != null) + { + output.Write(",\"Exception\":"); + JsonValueFormatter.WriteQuotedJsonString(logEvent.Exception.ToString(), output); + } + + if (logEvent.Properties.Count != 0) + { + WriteProperties(logEvent, output); + } + + output.Write('}'); + } + + private void WriteProperties(LogEvent logEvent, TextWriter output) + { + output.Write(",\"Properties\":{"); + + var messageTemplateProperties = logEvent.Properties + .Where(property => TemplateContainsPropertyName(logEvent.MessageTemplate, property.Key)) + .ToArray(); + + if (messageTemplateProperties.Length > 0) + { + WriteOpenNamespace(output); + + WriteProperties(messageTemplateProperties, output); + + // Better not to allocate an array in the 99.9% of cases where this is false + var tokensWithFormat = logEvent.MessageTemplate.Tokens + .OfType() + .Where(propertyToken => propertyToken.Format != null); + + // ReSharper disable once PossibleMultipleEnumeration + if (tokensWithFormat.Any()) + { + // ReSharper disable once PossibleMultipleEnumeration + WriteRenderings(tokensWithFormat.GroupBy(pt => pt.PropertyName), logEvent.Properties, output); + } + + WriteCloseNamespace(output); + } + + var enrichedProperties = logEvent.Properties + .Except(messageTemplateProperties) + .ToArray(); + + if (enrichedProperties.Length > 0) + { + if (messageTemplateProperties.Length > 0) + { + output.Write(","); + } + + WriteProperties(enrichedProperties, output); + } + + output.Write('}'); + } + + private void WriteOpenNamespace(TextWriter output) + { + output.Write(subComponent != null ? + $"\"{component}\":{{\"{subComponent}\":{{" : + $"\"{component}\":{{"); + } + + private void WriteCloseNamespace(TextWriter output) + { + output.Write(subComponent != null ? "}}" : "}"); + } + + private static void WriteProperties(IEnumerable> properties, TextWriter output) + { + var precedingDelimiter = ""; + + foreach (var property in properties) + { + output.Write(precedingDelimiter); + precedingDelimiter = ","; + + JsonValueFormatter.WriteQuotedJsonString(property.Key, output); + output.Write(':'); + ValueFormatter.Instance.Format(property.Value, output); + } + } + + private static bool TemplateContainsPropertyName(MessageTemplate template, string propertyName) + { + foreach (var token in template.Tokens) + { + if (token is PropertyToken namedProperty && + namedProperty.PropertyName == propertyName) + { + return true; + } + } + + return false; + } + + private static void WriteRenderings( + IEnumerable> tokensWithFormat, + IReadOnlyDictionary properties, + TextWriter output) + { + output.Write(",\"Renderings\":{"); + + var rdelim = ""; + foreach (var ptoken in tokensWithFormat) + { + output.Write(rdelim); + rdelim = ","; + + JsonValueFormatter.WriteQuotedJsonString(ptoken.Key, output); + output.Write(":["); + + var fdelim = ""; + foreach (var format in ptoken) + { + output.Write(fdelim); + fdelim = ","; + + output.Write("{\"Format\":"); + JsonValueFormatter.WriteQuotedJsonString(format.Format, output); + + output.Write(",\"Rendering\":"); + var sw = new StringWriter(); + format.Render(properties, sw); + JsonValueFormatter.WriteQuotedJsonString(sw.ToString(), output); + output.Write('}'); + } + + output.Write(']'); + } + + output.Write('}'); + } + + private static void LogNonFormattableEvent(LogEvent logEvent, Exception e) + { + SelfLog.WriteLine( + "Event at {0} with message template {1} could not be formatted into JSON and will be dropped: {2}", + logEvent.Timestamp.ToString("o"), + logEvent.MessageTemplate.Text, + e); + } + } +} diff --git a/src/Serilog.Sinks.Http/Sinks/Http/TextFormatters/NormalRenderedTextFormatter.cs b/src/Serilog.Sinks.Http/Sinks/Http/TextFormatters/NormalRenderedTextFormatter.cs index ffaa9400..04a2f124 100644 --- a/src/Serilog.Sinks.Http/Sinks/Http/TextFormatters/NormalRenderedTextFormatter.cs +++ b/src/Serilog.Sinks.Http/Sinks/Http/TextFormatters/NormalRenderedTextFormatter.cs @@ -24,6 +24,7 @@ namespace Serilog.Sinks.Http.TextFormatters /// /// /// + /// /// public class NormalRenderedTextFormatter : NormalTextFormatter { diff --git a/src/Serilog.Sinks.Http/Sinks/Http/TextFormatters/NormalTextFormatter.cs b/src/Serilog.Sinks.Http/Sinks/Http/TextFormatters/NormalTextFormatter.cs index 19854476..ac49c295 100644 --- a/src/Serilog.Sinks.Http/Sinks/Http/TextFormatters/NormalTextFormatter.cs +++ b/src/Serilog.Sinks.Http/Sinks/Http/TextFormatters/NormalTextFormatter.cs @@ -33,6 +33,7 @@ namespace Serilog.Sinks.Http.TextFormatters /// /// /// + /// /// public class NormalTextFormatter : ITextFormatter { @@ -64,10 +65,8 @@ public void Format(LogEvent logEvent, TextWriter output) private void FormatContent(LogEvent logEvent, TextWriter output) { - if (logEvent == null) - throw new ArgumentNullException(nameof(logEvent)); - if (output == null) - throw new ArgumentNullException(nameof(output)); + if (logEvent == null) throw new ArgumentNullException(nameof(logEvent)); + if (output == null) throw new ArgumentNullException(nameof(output)); output.Write("{\"Timestamp\":\""); output.Write(logEvent.Timestamp.ToString("o")); diff --git a/test/Serilog.Sinks.Http.LogServer/Controllers/Dto/CompactEventDto.cs b/test/Serilog.Sinks.Http.LogServer/Controllers/Dto/CompactEventDto.cs deleted file mode 100644 index 09a90e48..00000000 --- a/test/Serilog.Sinks.Http.LogServer/Controllers/Dto/CompactEventDto.cs +++ /dev/null @@ -1,26 +0,0 @@ -using System; -using Newtonsoft.Json; - -namespace Serilog.Sinks.Http.LogServer.Controllers.Dto -{ - public class CompactEventDto - { - [JsonProperty("@t")] - public DateTime Timestamp { get; set; } - - [JsonProperty("@l")] - public string Level { get; set; } - - [JsonProperty("@mt")] - public string MessageTemplate { get; set; } - - [JsonProperty("@m")] - public string RenderedMessage { get; set; } - - [JsonProperty("@x")] - public string Exception { get; set; } - - [JsonProperty("@r")] - public string[] Renderings { get; set; } - } -} diff --git a/test/Serilog.Sinks.Http.LogServer/Controllers/Dto/RenderingDto.cs b/test/Serilog.Sinks.Http.LogServer/Controllers/Dto/RenderingDto.cs index c6e326a2..16a3a427 100644 --- a/test/Serilog.Sinks.Http.LogServer/Controllers/Dto/RenderingDto.cs +++ b/test/Serilog.Sinks.Http.LogServer/Controllers/Dto/RenderingDto.cs @@ -8,9 +8,7 @@ public class RenderingDto public override bool Equals(object obj) { - var other = obj as RenderingDto; - - if (other == null) + if (!(obj is RenderingDto other)) return false; return diff --git a/test/Serilog.Sinks.HttpTests/Sinks/Http/TextFormatters/CompactTextFormatterTest.cs b/test/Serilog.Sinks.HttpTests/Sinks/Http/TextFormatters/CompactTextFormatterTest.cs index b5a25d46..7ed003a1 100644 --- a/test/Serilog.Sinks.HttpTests/Sinks/Http/TextFormatters/CompactTextFormatterTest.cs +++ b/test/Serilog.Sinks.HttpTests/Sinks/Http/TextFormatters/CompactTextFormatterTest.cs @@ -1,9 +1,9 @@ using System; using System.IO; -using Newtonsoft.Json; +using System.Linq; +using Newtonsoft.Json.Linq; using Serilog.Events; using Serilog.Formatting; -using Serilog.Sinks.Http.LogServer.Controllers.Dto; using Serilog.Support; using Shouldly; using Xunit; @@ -28,7 +28,7 @@ public CompactTextFormatterTest() [InlineData(LogEventLevel.Warning)] [InlineData(LogEventLevel.Error)] [InlineData(LogEventLevel.Fatal)] - public void LogEventLevels(LogEventLevel level) + public void Level(LogEventLevel level) { // Arrange logger = CreateLogger(new CompactRenderedTextFormatter()); @@ -41,18 +41,18 @@ public void LogEventLevels(LogEventLevel level) if (level == LogEventLevel.Information) { - @event.Level.ShouldBeNull(); + @event["@l"].ShouldBeNull(); } else { - @event.Level.ShouldNotBeNull(); + @event["@l"].ShouldNotBeNull(); } } [Theory] [InlineData(true)] [InlineData(false)] - public void EmptyEvent(bool isRenderingMessage) + public void Message(bool isRenderingMessage) { // Arrange logger = CreateLogger(isRenderingMessage ? @@ -64,18 +64,18 @@ public void EmptyEvent(bool isRenderingMessage) // Assert var @event = GetEvent(); - @event.Timestamp.ShouldNotBeNull(); - @event.Level.ShouldBeNull(); - @event.MessageTemplate.ShouldBe("No properties"); - @event.RenderedMessage.ShouldBe(isRenderingMessage ? "No properties" : null); - @event.Exception.ShouldBeNull(); - @event.Renderings.ShouldBeNull(); + @event["@t"].ShouldNotBeNull(); + @event["@l"].ShouldBeNull(); + @event["@mt"].ShouldBe("No properties"); + ((string)@event["@m"]).ShouldBe(isRenderingMessage ? "No properties" : null); + @event["@x"].ShouldBeNull(); + @event["@r"].ShouldBeNull(); } [Theory] [InlineData(true)] [InlineData(false)] - public void MinimalEvent(bool isRenderingMessage) + public void PropertyInMessageTemplate(bool isRenderingMessage) { // Arrange logger = CreateLogger(isRenderingMessage ? @@ -87,18 +87,18 @@ public void MinimalEvent(bool isRenderingMessage) // Assert var @event = GetEvent(); - @event.Timestamp.ShouldNotBeNull(); - @event.MessageTemplate.ShouldBe("One {Property}"); - @event.RenderedMessage.ShouldBe(isRenderingMessage ? "One 42" : null); - @event.Exception.ShouldBeNull(); - GetProperty("Property").ShouldBe("42"); - @event.Renderings.ShouldBeNull(); + @event["@t"].ShouldNotBeNull(); + @event["@mt"].ShouldBe("One {Property}"); + ((string)@event["@m"]).ShouldBe(isRenderingMessage ? "One 42" : null); + @event["@x"].ShouldBeNull(); + @event["Property"].ShouldBe(42); + @event["@r"].ShouldBeNull(); } [Theory] [InlineData(true)] [InlineData(false)] - public void MultipleProperties(bool isRenderingMessage) + public void PropertiesInMessageTemplate(bool isRenderingMessage) { // Arrange logger = CreateLogger(isRenderingMessage ? @@ -110,19 +110,19 @@ public void MultipleProperties(bool isRenderingMessage) // Assert var @event = GetEvent(); - @event.Timestamp.ShouldNotBeNull(); - @event.MessageTemplate.ShouldBe("Property {First} and {Second}"); - @event.RenderedMessage.ShouldBe(isRenderingMessage ? "Property \"One\" and \"Two\"" : null); - @event.Exception.ShouldBeNull(); - GetProperty("First").ShouldBe("One"); - GetProperty("Second").ShouldBe("Two"); - @event.Renderings.ShouldBeNull(); + @event["@t"].ShouldNotBeNull(); + @event["@mt"].ShouldBe("Property {First} and {Second}"); + ((string)@event["@m"]).ShouldBe(isRenderingMessage ? "Property \"One\" and \"Two\"" : null); + @event["@x"].ShouldBeNull(); + @event["First"].ShouldBe("One"); + @event["Second"].ShouldBe("Two"); + @event["@r"].ShouldBeNull(); } [Theory] [InlineData(true)] [InlineData(false)] - public void Exceptions(bool isRenderingMessage) + public void EnrichedProperties(bool isRenderingMessage) { // Arrange logger = CreateLogger(isRenderingMessage ? @@ -130,21 +130,26 @@ public void Exceptions(bool isRenderingMessage) new CompactTextFormatter()); // Act - logger.Information(new DivideByZeroException(), "With exception"); + logger + .ForContext("First", "One") + .ForContext("Second", "Two") + .Information("No properties"); // Assert var @event = GetEvent(); - @event.Timestamp.ShouldNotBeNull(); - @event.MessageTemplate.ShouldBe("With exception"); - @event.RenderedMessage.ShouldBe(isRenderingMessage ? "With exception" : null); - @event.Exception.ShouldNotBeNull(); - @event.Renderings.ShouldBeNull(); + @event["@t"].ShouldNotBeNull(); + @event["@mt"].ShouldBe("No properties"); + ((string)@event["@m"]).ShouldBe(isRenderingMessage ? "No properties" : null); + @event["@x"].ShouldBeNull(); + @event["First"].ShouldBe("One"); + @event["Second"].ShouldBe("Two"); + @event["@r"].ShouldBeNull(); } [Theory] [InlineData(true)] [InlineData(false)] - public void ExceptionAndProperties(bool isRenderingMessage) + public void Rendering(bool isRenderingMessage) { // Arrange logger = CreateLogger(isRenderingMessage ? @@ -152,16 +157,16 @@ public void ExceptionAndProperties(bool isRenderingMessage) new CompactTextFormatter()); // Act - logger.Information(new DivideByZeroException(), "With exception and {Property}", 42); + logger.Information("One {Rendering:x8}", 42); // Assert var @event = GetEvent(); - @event.Timestamp.ShouldNotBeNull(); - @event.MessageTemplate.ShouldBe("With exception and {Property}"); - @event.RenderedMessage.ShouldBe(isRenderingMessage ? "With exception and 42" : null); - @event.Exception.ShouldNotBeNull(); - GetProperty("Property").ShouldBe("42"); - @event.Renderings.ShouldBeNull(); + @event["@t"].ShouldNotBeNull(); + @event["@mt"].ShouldBe("One {Rendering:x8}"); + ((string)@event["@m"]).ShouldBe(isRenderingMessage ? "One 0000002a" : null); + @event["@x"].ShouldBeNull(); + @event["Rendering"].ShouldBe(42); + @event["@r"].Select(token => token.Value()).ShouldBe(new[] { "0000002a" }); } [Theory] @@ -175,22 +180,23 @@ public void Renderings(bool isRenderingMessage) new CompactTextFormatter()); // Act - logger.Information("One {Rendering:x8}", 42); + logger.Information("Rendering {First:x8} and {Second:x8}", 1, 2); // Assert var @event = GetEvent(); - @event.Timestamp.ShouldNotBeNull(); - @event.MessageTemplate.ShouldBe("One {Rendering:x8}"); - @event.RenderedMessage.ShouldBe(isRenderingMessage ? "One 0000002a" : null); - @event.Exception.ShouldBeNull(); - GetProperty("Rendering").ShouldBe("42"); - @event.Renderings.ShouldBe(new[] { "0000002a" }); + @event["@t"].ShouldNotBeNull(); + @event["@mt"].ShouldBe("Rendering {First:x8} and {Second:x8}"); + ((string)@event["@m"]).ShouldBe(isRenderingMessage ? "Rendering 00000001 and 00000002" : null); + @event["@x"].ShouldBeNull(); + @event["First"].ShouldBe(1); + @event["Second"].ShouldBe(2); + @event["@r"].Children().Select(token => token.Value()).ShouldBe(new[] { "00000001", "00000002" }); } [Theory] [InlineData(true)] [InlineData(false)] - public void MultipleRenderings(bool isRenderingMessage) + public void Exception(bool isRenderingMessage) { // Arrange logger = CreateLogger(isRenderingMessage ? @@ -198,17 +204,38 @@ public void MultipleRenderings(bool isRenderingMessage) new CompactTextFormatter()); // Act - logger.Information("Rendering {First:x8} and {Second:x8}", 1, 2); + logger.Information(new DivideByZeroException(), "With exception"); + + // Assert + var @event = GetEvent(); + @event["@t"].ShouldNotBeNull(); + @event["@mt"].ShouldBe("With exception"); + ((string)@event["@m"]).ShouldBe(isRenderingMessage ? "With exception" : null); + @event["@x"].ShouldNotBeNull(); + @event["@r"].ShouldBeNull(); + } + + [Theory] + [InlineData(true)] + [InlineData(false)] + public void ExceptionAndProperty(bool isRenderingMessage) + { + // Arrange + logger = CreateLogger(isRenderingMessage ? + new CompactRenderedTextFormatter() : + new CompactTextFormatter()); + + // Act + logger.Information(new DivideByZeroException(), "With exception and {Property}", 42); // Assert var @event = GetEvent(); - @event.Timestamp.ShouldNotBeNull(); - @event.MessageTemplate.ShouldBe("Rendering {First:x8} and {Second:x8}"); - @event.RenderedMessage.ShouldBe(isRenderingMessage ? "Rendering 00000001 and 00000002" : null); - @event.Exception.ShouldBeNull(); - GetProperty("First").ShouldBe("1"); - GetProperty("Second").ShouldBe("2"); - @event.Renderings.ShouldBe(new[] { "00000001", "00000002" }); + @event["@t"].ShouldNotBeNull(); + @event["@mt"].ShouldBe("With exception and {Property}"); + ((string)@event["@m"]).ShouldBe(isRenderingMessage ? "With exception and 42" : null); + @event["@x"].ShouldNotBeNull(); + @event["Property"].ShouldBe(42); + @event["@r"].ShouldBeNull(); } [Theory] @@ -236,15 +263,9 @@ private ILogger CreateLogger(ITextFormatter formatter) .CreateLogger(); } - private CompactEventDto GetEvent() - { - return JsonConvert.DeserializeObject(output.ToString()); - } - - private string GetProperty(string name) + private JObject GetEvent() { - dynamic @event = JsonConvert.DeserializeObject(output.ToString()); - return @event[name]; + return JObject.Parse(output.ToString()); } } } diff --git a/test/Serilog.Sinks.HttpTests/Sinks/Http/TextFormatters/NamespacedTextFormatterTest.cs b/test/Serilog.Sinks.HttpTests/Sinks/Http/TextFormatters/NamespacedTextFormatterTest.cs new file mode 100644 index 00000000..598e507b --- /dev/null +++ b/test/Serilog.Sinks.HttpTests/Sinks/Http/TextFormatters/NamespacedTextFormatterTest.cs @@ -0,0 +1,457 @@ +using System; +using System.IO; +using System.Linq; +using Newtonsoft.Json.Linq; +using Serilog.Events; +using Serilog.Formatting; +using Serilog.Support; +using Shouldly; +using Xunit; + +namespace Serilog.Sinks.Http.TextFormatters +{ + public class NamespacedTextFormatterTest + { + private readonly StringWriter output; + + private ILogger logger; + + public NamespacedTextFormatterTest() + { + output = new StringWriter(); + } + + [Theory] + [InlineData(LogEventLevel.Verbose)] + [InlineData(LogEventLevel.Debug)] + [InlineData(LogEventLevel.Information)] + [InlineData(LogEventLevel.Warning)] + [InlineData(LogEventLevel.Error)] + [InlineData(LogEventLevel.Fatal)] + public void Level(LogEventLevel level) + { + // Arrange + logger = CreateLogger(new Formatter("Foo", "Bar", true)); + + // Act + logger.Write(level, "No properties"); + + // Assert + var @event = GetEvent(); + @event["Level"].ShouldNotBeNull(); + } + + [Theory] + [InlineData(true)] + [InlineData(false)] + public void Message(bool isRenderingMessage) + { + // Arrange + logger = CreateLogger(new Formatter("Foo", "Bar", isRenderingMessage)); + + // Act + logger.Information("No properties"); + + // Assert + var @event = GetEvent(); + @event["Timestamp"].ShouldNotBeNull(); + @event["Level"].ShouldBe("Information"); + @event["MessageTemplate"].ShouldBe("No properties"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "No properties" : null); + @event["Exception"].ShouldBeNull(); + @event["Properties"].ShouldBeNull(); + } + + [Theory] + [InlineData(true)] + [InlineData(false)] + public void PropertyInMessageTemplateUsingComponentNamespace(bool isRenderingMessage) + { + // Arrange + logger = CreateLogger(new Formatter("Foo", null, isRenderingMessage)); + + // Act + logger.Information("One {Property}", 42); + + // Assert + var @event = GetEvent(); + @event["Timestamp"].ShouldNotBeNull(); + @event["Level"].ShouldBe("Information"); + @event["MessageTemplate"].ShouldBe("One {Property}"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "One 42" : null); + @event["Exception"].ShouldBeNull(); + @event["Properties"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"]["Property"].ShouldBe(42); + } + + [Theory] + [InlineData(true)] + [InlineData(false)] + public void PropertyInMessageTemplateUsingSubComponentNamespace(bool isRenderingMessage) + { + // Arrange + logger = CreateLogger(new Formatter("Foo", "Bar", isRenderingMessage)); + + // Act + logger.Information("One {Property}", 42); + + // Assert + var @event = GetEvent(); + @event["Timestamp"].ShouldNotBeNull(); + @event["Level"].ShouldBe("Information"); + @event["MessageTemplate"].ShouldBe("One {Property}"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "One 42" : null); + @event["Exception"].ShouldBeNull(); + @event["Properties"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"]["Bar"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"]["Bar"]["Property"].ShouldBe(42); + } + + [Theory] + [InlineData(true)] + [InlineData(false)] + public void PropertiesInMessageTemplateUsingComponentNamespace(bool isRenderingMessage) + { + // Arrange + logger = CreateLogger(new Formatter("Foo", null, isRenderingMessage)); + + // Act + logger.Information("Property {First} and {Second}", "One", "Two"); + + // Assert + var @event = GetEvent(); + @event["Timestamp"].ShouldNotBeNull(); + @event["Level"].ShouldBe("Information"); + @event["MessageTemplate"].ShouldBe("Property {First} and {Second}"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "Property \"One\" and \"Two\"" : null); + @event["Exception"].ShouldBeNull(); + @event["Properties"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"].Children().Count().ShouldBe(2); + @event["Properties"]["Foo"]["First"].ShouldBe("One"); + @event["Properties"]["Foo"]["Second"].ShouldBe("Two"); + } + + [Theory] + [InlineData(true)] + [InlineData(false)] + public void PropertiesInMessageTemplateUsingSubComponentNamespace(bool isRenderingMessage) + { + // Arrange + logger = CreateLogger(new Formatter("Foo", "Bar", isRenderingMessage)); + + // Act + logger.Information("Property {First} and {Second}", "One", "Two"); + + // Assert + var @event = GetEvent(); + @event["Timestamp"].ShouldNotBeNull(); + @event["Level"].ShouldBe("Information"); + @event["MessageTemplate"].ShouldBe("Property {First} and {Second}"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "Property \"One\" and \"Two\"" : null); + @event["Exception"].ShouldBeNull(); + @event["Properties"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"]["Bar"].Children().Count().ShouldBe(2); + @event["Properties"]["Foo"]["Bar"]["First"].ShouldBe("One"); + @event["Properties"]["Foo"]["Bar"]["Second"].ShouldBe("Two"); + } + + [Theory] + [InlineData(true)] + [InlineData(false)] + public void EnrichedProperties(bool isRenderingMessage) + { + // Arrange + logger = CreateLogger(new Formatter("Foo", "Bar", isRenderingMessage)); + + // Act + logger + .ForContext("FirstContext", "One") + .ForContext("SecondContext", "Two") + .Information("No properties"); + + // Assert + var @event = GetEvent(); + @event["Timestamp"].ShouldNotBeNull(); + @event["MessageTemplate"].ShouldBe("No properties"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "No properties" : null); + @event["Exception"].ShouldBeNull(); + @event["Properties"].Children().Count().ShouldBe(2); + @event["Properties"]["FirstContext"].ShouldBe("One"); + @event["Properties"]["SecondContext"].ShouldBe("Two"); + } + + [Theory] + [InlineData(true)] + [InlineData(false)] + public void PropertyInMessageTemplateAndEnrichedPropertyUsingComponentNamespace(bool isRenderingMessage) + { + + // Arrange + logger = CreateLogger(new Formatter("Foo", null, isRenderingMessage)); + + // Act + logger + .ForContext("FirstContext", "One") + .Information("One {Property}", 42); + + // Assert + var @event = GetEvent(); + @event["Timestamp"].ShouldNotBeNull(); + @event["MessageTemplate"].ShouldBe("One {Property}"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "One 42" : null); + @event["Exception"].ShouldBeNull(); + @event["Properties"].Children().Count().ShouldBe(2); + @event["Properties"]["FirstContext"].ShouldBe("One"); + @event["Properties"]["Foo"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"]["Property"].ShouldBe(42); + } + + [Theory] + [InlineData(true)] + [InlineData(false)] + public void PropertyInMessageTemplateAndEnrichedPropertyUsingSubComponentNamespace(bool isRenderingMessage) + { + // Arrange + logger = CreateLogger(new Formatter("Foo", "Bar", isRenderingMessage)); + + // Act + logger + .ForContext("FirstContext", "One") + .Information("One {Property}", 42); + + // Assert + var @event = GetEvent(); + @event["Timestamp"].ShouldNotBeNull(); + @event["MessageTemplate"].ShouldBe("One {Property}"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "One 42" : null); + @event["Exception"].ShouldBeNull(); + @event["Properties"].Children().Count().ShouldBe(2); + @event["Properties"]["FirstContext"].ShouldBe("One"); + @event["Properties"]["Foo"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"]["Bar"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"]["Bar"]["Property"].ShouldBe(42); + } + + [Theory] + [InlineData(true)] + [InlineData(false)] + public void RenderingUsingComponentNamespace(bool isRenderingMessage) + { + // Arrange + logger = CreateLogger(new Formatter("Foo", null, isRenderingMessage)); + + // Act + logger.Information("One {Rendering:x8}", 42); + + // Assert + var @event = GetEvent(); + @event["Timestamp"].ShouldNotBeNull(); + @event["Level"].ShouldBe("Information"); + @event["MessageTemplate"].ShouldBe("One {Rendering:x8}"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "One 0000002a" : null); + @event["Exception"].ShouldBeNull(); + @event["Properties"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"].Children().Count().ShouldBe(2); + @event["Properties"]["Foo"]["Rendering"].ShouldBe(42); + @event["Properties"]["Foo"]["Renderings"]["Rendering"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"]["Renderings"]["Rendering"][0]["Format"].ShouldBe("x8"); + @event["Properties"]["Foo"]["Renderings"]["Rendering"][0]["Rendering"].ShouldBe("0000002a"); + } + + [Theory] + [InlineData(true)] + [InlineData(false)] + public void RenderingUsingSubComponentNamespace(bool isRenderingMessage) + { + // Arrange + logger = CreateLogger(new Formatter("Foo", "Bar", isRenderingMessage)); + + // Act + logger.Information("One {Rendering:x8}", 42); + + // Assert + var @event = GetEvent(); + @event["Timestamp"].ShouldNotBeNull(); + @event["Level"].ShouldBe("Information"); + @event["MessageTemplate"].ShouldBe("One {Rendering:x8}"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "One 0000002a" : null); + @event["Exception"].ShouldBeNull(); + @event["Properties"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"]["Bar"].Children().Count().ShouldBe(2); + @event["Properties"]["Foo"]["Bar"]["Rendering"].ShouldBe(42); + @event["Properties"]["Foo"]["Bar"]["Renderings"]["Rendering"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"]["Bar"]["Renderings"]["Rendering"][0]["Format"].ShouldBe("x8"); + @event["Properties"]["Foo"]["Bar"]["Renderings"]["Rendering"][0]["Rendering"].ShouldBe("0000002a"); + } + + [Theory] + [InlineData(true)] + [InlineData(false)] + public void RenderingsUsingComponentNamespace(bool isRenderingMessage) + { + // Arrange + logger = CreateLogger(new Formatter("Foo", null, isRenderingMessage)); + + // Act + logger.Information("Rendering {First:x8} and {Second:x8}", 1, 2); + + // Assert + var @event = GetEvent(); + @event["Timestamp"].ShouldNotBeNull(); + @event["Level"].ShouldBe("Information"); + @event["MessageTemplate"].ShouldBe("Rendering {First:x8} and {Second:x8}"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "Rendering 00000001 and 00000002" : null); + @event["Exception"].ShouldBeNull(); + @event["Properties"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"].Children().Count().ShouldBe(3); + @event["Properties"]["Foo"]["First"].ShouldBe(1); + @event["Properties"]["Foo"]["Second"].ShouldBe(2); + @event["Properties"]["Foo"]["Renderings"]["First"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"]["Renderings"]["First"][0]["Format"].ShouldBe("x8"); + @event["Properties"]["Foo"]["Renderings"]["First"][0]["Rendering"].ShouldBe("00000001"); + @event["Properties"]["Foo"]["Renderings"]["Second"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"]["Renderings"]["Second"][0]["Format"].ShouldBe("x8"); + @event["Properties"]["Foo"]["Renderings"]["Second"][0]["Rendering"].ShouldBe("00000002"); + } + + [Theory] + [InlineData(true)] + [InlineData(false)] + public void RenderingsUsingSubComponentNamespace(bool isRenderingMessage) + { + // Arrange + logger = CreateLogger(new Formatter("Foo", "Bar", isRenderingMessage)); + + // Act + logger.Information("Rendering {First:x8} and {Second:x8}", 1, 2); + + // Assert + var @event = GetEvent(); + @event["Timestamp"].ShouldNotBeNull(); + @event["Level"].ShouldBe("Information"); + @event["MessageTemplate"].ShouldBe("Rendering {First:x8} and {Second:x8}"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "Rendering 00000001 and 00000002" : null); + @event["Exception"].ShouldBeNull(); + @event["Properties"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"]["Bar"].Children().Count().ShouldBe(3); + @event["Properties"]["Foo"]["Bar"]["First"].ShouldBe(1); + @event["Properties"]["Foo"]["Bar"]["Second"].ShouldBe(2); + @event["Properties"]["Foo"]["Bar"]["Renderings"]["First"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"]["Bar"]["Renderings"]["First"][0]["Format"].ShouldBe("x8"); + @event["Properties"]["Foo"]["Bar"]["Renderings"]["First"][0]["Rendering"].ShouldBe("00000001"); + @event["Properties"]["Foo"]["Bar"]["Renderings"]["Second"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"]["Bar"]["Renderings"]["Second"][0]["Format"].ShouldBe("x8"); + @event["Properties"]["Foo"]["Bar"]["Renderings"]["Second"][0]["Rendering"].ShouldBe("00000002"); + } + + [Theory] + [InlineData(true)] + [InlineData(false)] + public void Exception(bool isRenderingMessage) + { + // Arrange + logger = CreateLogger(new Formatter("Foo", "Bar", isRenderingMessage)); + + // Act + logger.Information(new DivideByZeroException(), "With exception"); + + // Assert + var @event = GetEvent(); + @event["Timestamp"].ShouldNotBeNull(); + @event["Level"].ShouldBe("Information"); + @event["MessageTemplate"].ShouldBe("With exception"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "With exception" : null); + @event["Exception"].ShouldNotBeNull(); + @event["Properties"].ShouldBeNull(); + } + + [Theory] + [InlineData(true)] + [InlineData(false)] + public void ExceptionAndPropertyUsingComponentNamespace(bool isRenderingMessage) + { + // Arrange + logger = CreateLogger(new Formatter("Foo", null, isRenderingMessage)); + + // Act + logger.Information(new DivideByZeroException(), "With exception and {Property}", 42); + + // Assert + var @event = GetEvent(); + @event["Timestamp"].ShouldNotBeNull(); + @event["Level"].ShouldBe("Information"); + @event["MessageTemplate"].ShouldBe("With exception and {Property}"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "With exception and 42" : null); + @event["Exception"].ShouldNotBeNull(); + @event["Properties"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"]["Property"].ShouldBe(42); + } + + [Theory] + [InlineData(true)] + [InlineData(false)] + public void ExceptionAndPropertyUsingSubComponentNamespace(bool isRenderingMessage) + { + // Arrange + logger = CreateLogger(new Formatter("Foo", "Bar", isRenderingMessage)); + + // Act + logger.Information(new DivideByZeroException(), "With exception and {Property}", 42); + + // Assert + var @event = GetEvent(); + @event["Timestamp"].ShouldNotBeNull(); + @event["Level"].ShouldBe("Information"); + @event["MessageTemplate"].ShouldBe("With exception and {Property}"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "With exception and 42" : null); + @event["Exception"].ShouldNotBeNull(); + @event["Properties"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"]["Bar"].Children().Count().ShouldBe(1); + @event["Properties"]["Foo"]["Bar"]["Property"].ShouldBe(42); + } + + [Theory] + [InlineData(true)] + [InlineData(false)] + public void NastyException(bool isRenderingMessage) + { + // Arrange + logger = CreateLogger(new Formatter("Foo", "Bar", isRenderingMessage)); + + // Act + logger.Information(new NastyException(), "With exception"); + + // Assert + output.ToString().ShouldBe(string.Empty); + } + + private ILogger CreateLogger(ITextFormatter formatter) + { + return new LoggerConfiguration() + .MinimumLevel.Verbose() + .WriteTo.Sink(new TextWriterSink(output, formatter)) + .CreateLogger(); + } + + private JObject GetEvent() + { + return JObject.Parse(output.ToString()); + } + + private class Formatter : NamespacedTextFormatter + { + public Formatter(string component, string subComponent, bool isRenderingMessage) + : base(component, subComponent) + { + IsRenderingMessage = isRenderingMessage; + } + } + } +} diff --git a/test/Serilog.Sinks.HttpTests/Sinks/Http/TextFormatters/NormalTextFormatterTest.cs b/test/Serilog.Sinks.HttpTests/Sinks/Http/TextFormatters/NormalTextFormatterTest.cs index 52150dc6..caa67745 100644 --- a/test/Serilog.Sinks.HttpTests/Sinks/Http/TextFormatters/NormalTextFormatterTest.cs +++ b/test/Serilog.Sinks.HttpTests/Sinks/Http/TextFormatters/NormalTextFormatterTest.cs @@ -1,10 +1,9 @@ using System; -using System.Collections.Generic; using System.IO; -using Newtonsoft.Json; +using System.Linq; +using Newtonsoft.Json.Linq; using Serilog.Events; using Serilog.Formatting; -using Serilog.Sinks.Http.LogServer.Controllers.Dto; using Serilog.Support; using Shouldly; using Xunit; @@ -29,7 +28,7 @@ public NormalTextFormatterTest() [InlineData(LogEventLevel.Warning)] [InlineData(LogEventLevel.Error)] [InlineData(LogEventLevel.Fatal)] - public void LogEventLevels(LogEventLevel level) + public void Level(LogEventLevel level) { // Arrange logger = CreateLogger(new NormalRenderedTextFormatter()); @@ -39,13 +38,13 @@ public void LogEventLevels(LogEventLevel level) // Assert var @event = GetEvent(); - @event.Level.ShouldNotBeNull(); + @event["Level"].ShouldNotBeNull(); } [Theory] [InlineData(true)] [InlineData(false)] - public void EmptyEvent(bool isRenderingMessage) + public void Message(bool isRenderingMessage) { // Arrange logger = CreateLogger(isRenderingMessage ? @@ -57,19 +56,19 @@ public void EmptyEvent(bool isRenderingMessage) // Assert var @event = GetEvent(); - @event.Timestamp.ShouldNotBeNull(); - @event.Level.ShouldBe("Information"); - @event.MessageTemplate.ShouldBe("No properties"); - @event.RenderedMessage.ShouldBe(isRenderingMessage ? "No properties" : null); - @event.Exception.ShouldBeNull(); - @event.Properties.ShouldBeNull(); - @event.Renderings.ShouldBeNull(); + @event["Timestamp"].ShouldNotBeNull(); + @event["Level"].ShouldBe("Information"); + @event["MessageTemplate"].ShouldBe("No properties"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "No properties" : null); + @event["Exception"].ShouldBeNull(); + @event["Properties"].ShouldBeNull(); + @event["Renderings"].ShouldBeNull(); } [Theory] [InlineData(true)] [InlineData(false)] - public void MinimalEvent(bool isRenderingMessage) + public void PropertyInMessageTemplate(bool isRenderingMessage) { // Arrange logger = CreateLogger(isRenderingMessage ? @@ -81,19 +80,20 @@ public void MinimalEvent(bool isRenderingMessage) // Assert var @event = GetEvent(); - @event.Timestamp.ShouldNotBeNull(); - @event.Level.ShouldBe("Information"); - @event.MessageTemplate.ShouldBe("One {Property}"); - @event.RenderedMessage.ShouldBe(isRenderingMessage ? "One 42" : null); - @event.Exception.ShouldBeNull(); - @event.Properties.ShouldBe(new Dictionary { { "Property", "42" } }); - @event.Renderings.ShouldBeNull(); + @event["Timestamp"].ShouldNotBeNull(); + @event["Level"].ShouldBe("Information"); + @event["MessageTemplate"].ShouldBe("One {Property}"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "One 42" : null); + @event["Exception"].ShouldBeNull(); + @event["Properties"].Children().Count().ShouldBe(1); + @event["Properties"]["Property"].ShouldBe(42); + @event["Renderings"].ShouldBeNull(); } [Theory] [InlineData(true)] [InlineData(false)] - public void MultipleProperties(bool isRenderingMessage) + public void PropertiesInMessageTemplate(bool isRenderingMessage) { // Arrange logger = CreateLogger(isRenderingMessage ? @@ -105,19 +105,21 @@ public void MultipleProperties(bool isRenderingMessage) // Assert var @event = GetEvent(); - @event.Timestamp.ShouldNotBeNull(); - @event.Level.ShouldBe("Information"); - @event.MessageTemplate.ShouldBe("Property {First} and {Second}"); - @event.RenderedMessage.ShouldBe(isRenderingMessage ? "Property \"One\" and \"Two\"" : null); - @event.Exception.ShouldBeNull(); - @event.Properties.ShouldBe(new Dictionary { { "First", "One" }, { "Second", "Two" } }); - @event.Renderings.ShouldBeNull(); + @event["Timestamp"].ShouldNotBeNull(); + @event["Level"].ShouldBe("Information"); + @event["MessageTemplate"].ShouldBe("Property {First} and {Second}"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "Property \"One\" and \"Two\"" : null); + @event["Exception"].ShouldBeNull(); + @event["Properties"].Children().Count().ShouldBe(2); + @event["Properties"]["First"].ShouldBe("One"); + @event["Properties"]["Second"].ShouldBe("Two"); + @event["Renderings"].ShouldBeNull(); } [Theory] [InlineData(true)] [InlineData(false)] - public void Exceptions(bool isRenderingMessage) + public void EnrichedProperties(bool isRenderingMessage) { // Arrange logger = CreateLogger(isRenderingMessage ? @@ -125,23 +127,27 @@ public void Exceptions(bool isRenderingMessage) new NormalTextFormatter()); // Act - logger.Information(new DivideByZeroException(), "With exception"); + logger + .ForContext("First", "One") + .ForContext("Second", "Two") + .Information("No properties"); // Assert var @event = GetEvent(); - @event.Timestamp.ShouldNotBeNull(); - @event.Level.ShouldBe("Information"); - @event.MessageTemplate.ShouldBe("With exception"); - @event.RenderedMessage.ShouldBe(isRenderingMessage ? "With exception" : null); - @event.Exception.ShouldNotBeNull(); - @event.Properties.ShouldBeNull(); - @event.Renderings.ShouldBeNull(); + @event["Timestamp"].ShouldNotBeNull(); + @event["MessageTemplate"].ShouldBe("No properties"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "No properties" : null); + @event["Exception"].ShouldBeNull(); + @event["Properties"].Children().Count().ShouldBe(2); + @event["Properties"]["First"].ShouldBe("One"); + @event["Properties"]["Second"].ShouldBe("Two"); + @event["Renderings"].ShouldBeNull(); } [Theory] [InlineData(true)] [InlineData(false)] - public void ExceptionAndProperties(bool isRenderingMessage) + public void Rendering(bool isRenderingMessage) { // Arrange logger = CreateLogger(isRenderingMessage ? @@ -149,17 +155,20 @@ public void ExceptionAndProperties(bool isRenderingMessage) new NormalTextFormatter()); // Act - logger.Information(new DivideByZeroException(), "With exception and {Property}", 42); + logger.Information("One {Rendering:x8}", 42); // Assert var @event = GetEvent(); - @event.Timestamp.ShouldNotBeNull(); - @event.Level.ShouldBe("Information"); - @event.MessageTemplate.ShouldBe("With exception and {Property}"); - @event.RenderedMessage.ShouldBe(isRenderingMessage ? "With exception and 42" : null); - @event.Exception.ShouldNotBeNull(); - @event.Properties.ShouldBe(new Dictionary { { "Property", "42" } }); - @event.Renderings.ShouldBeNull(); + @event["Timestamp"].ShouldNotBeNull(); + @event["Level"].ShouldBe("Information"); + @event["MessageTemplate"].ShouldBe("One {Rendering:x8}"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "One 0000002a" : null); + @event["Exception"].ShouldBeNull(); + @event["Properties"].Children().Count().ShouldBe(1); + @event["Properties"]["Rendering"].ShouldBe(42); + @event["Renderings"]["Rendering"].Children().Count().ShouldBe(1); + @event["Renderings"]["Rendering"][0]["Format"].ShouldBe("x8"); + @event["Renderings"]["Rendering"][0]["Rendering"].ShouldBe("0000002a"); } [Theory] @@ -173,25 +182,30 @@ public void Renderings(bool isRenderingMessage) new NormalTextFormatter()); // Act - logger.Information("One {Rendering:x8}", 42); + logger.Information("Rendering {First:x8} and {Second:x8}", 1, 2); // Assert var @event = GetEvent(); - @event.Timestamp.ShouldNotBeNull(); - @event.Level.ShouldBe("Information"); - @event.MessageTemplate.ShouldBe("One {Rendering:x8}"); - @event.RenderedMessage.ShouldBe(isRenderingMessage ? "One 0000002a" : null); - @event.Exception.ShouldBeNull(); - @event.Properties.ShouldBe(new Dictionary { { "Rendering", "42" } }); - @event.Renderings.ShouldContainKey("Rendering"); - @event.Renderings["Rendering"].Length.ShouldBe(1); - @event.Renderings["Rendering"][0].ShouldBe(new RenderingDto { Format = "x8", Rendering = "0000002a" }); + @event["Timestamp"].ShouldNotBeNull(); + @event["Level"].ShouldBe("Information"); + @event["MessageTemplate"].ShouldBe("Rendering {First:x8} and {Second:x8}"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "Rendering 00000001 and 00000002" : null); + @event["Exception"].ShouldBeNull(); + @event["Properties"].Children().Count().ShouldBe(2); + @event["Properties"]["First"].ShouldBe(1); + @event["Properties"]["Second"].ShouldBe(2); + @event["Renderings"]["First"].Children().Count().ShouldBe(1); + @event["Renderings"]["First"][0]["Format"].ShouldBe("x8"); + @event["Renderings"]["First"][0]["Rendering"].ShouldBe("00000001"); + @event["Renderings"]["Second"].Children().Count().ShouldBe(1); + @event["Renderings"]["Second"][0]["Format"].ShouldBe("x8"); + @event["Renderings"]["Second"][0]["Rendering"].ShouldBe("00000002"); } [Theory] [InlineData(true)] [InlineData(false)] - public void MultipleRenderings(bool isRenderingMessage) + public void Exception(bool isRenderingMessage) { // Arrange logger = CreateLogger(isRenderingMessage ? @@ -199,22 +213,42 @@ public void MultipleRenderings(bool isRenderingMessage) new NormalTextFormatter()); // Act - logger.Information("Rendering {First:x8} and {Second:x8}", 1, 2); + logger.Information(new DivideByZeroException(), "With exception"); + + // Assert + var @event = GetEvent(); + @event["Timestamp"].ShouldNotBeNull(); + @event["Level"].ShouldBe("Information"); + @event["MessageTemplate"].ShouldBe("With exception"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "With exception" : null); + @event["Exception"].ShouldNotBeNull(); + @event["Properties"].ShouldBeNull(); + @event["Renderings"].ShouldBeNull(); + } + + [Theory] + [InlineData(true)] + [InlineData(false)] + public void ExceptionAndProperty(bool isRenderingMessage) + { + // Arrange + logger = CreateLogger(isRenderingMessage ? + new NormalRenderedTextFormatter() : + new NormalTextFormatter()); + + // Act + logger.Information(new DivideByZeroException(), "With exception and {Property}", 42); // Assert var @event = GetEvent(); - @event.Timestamp.ShouldNotBeNull(); - @event.Level.ShouldBe("Information"); - @event.MessageTemplate.ShouldBe("Rendering {First:x8} and {Second:x8}"); - @event.RenderedMessage.ShouldBe(isRenderingMessage ? "Rendering 00000001 and 00000002" : null); - @event.Exception.ShouldBeNull(); - @event.Properties.ShouldBe(new Dictionary { { "First", "1" }, { "Second", "2" } }); - @event.Renderings.ShouldContainKey("First"); - @event.Renderings["First"].Length.ShouldBe(1); - @event.Renderings["First"][0].ShouldBe(new RenderingDto { Format = "x8", Rendering = "00000001" }); - @event.Renderings.ShouldContainKey("Second"); - @event.Renderings["Second"].Length.ShouldBe(1); - @event.Renderings["Second"][0].ShouldBe(new RenderingDto { Format = "x8", Rendering = "00000002" }); + @event["Timestamp"].ShouldNotBeNull(); + @event["Level"].ShouldBe("Information"); + @event["MessageTemplate"].ShouldBe("With exception and {Property}"); + ((string)@event["RenderedMessage"]).ShouldBe(isRenderingMessage ? "With exception and 42" : null); + @event["Exception"].ShouldNotBeNull(); + @event["Properties"].Children().Count().ShouldBe(1); + @event["Properties"]["Property"].ShouldBe(42); + @event["Renderings"].ShouldBeNull(); } [Theory] @@ -242,9 +276,9 @@ private ILogger CreateLogger(ITextFormatter formatter) .CreateLogger(); } - private EventDto GetEvent() + private JObject GetEvent() { - return JsonConvert.DeserializeObject(output.ToString()); + return JObject.Parse(output.ToString()); } } }