diff --git a/README.md b/README.md index 034dc34..b90e943 100644 --- a/README.md +++ b/README.md @@ -3,7 +3,7 @@ log4net-loggly Custom log4net appenders for importing logging events to loggly. It’s asynchronous and will send logs in the background without blocking your application. Check out Loggly's [.Net logging documentation](https://www.loggly.com/docs/net-logs/) to learn more. -Note: This library also has a support for .NET Core applications. Please see the section [.NET Core Support](README.md#net-core-support) below. +**Note:** This library supports both .NET 4.0 and .NET Standard 2.0. Please see the section **[.NET Core Support](README.md#net-core-support)** below. Download log4net-loggly package from NuGet. Use the following command. @@ -14,79 +14,86 @@ Add the following code in your web.config to configure LogglyAppender in your ap
- + - - + + - - - - - - + + + + + - + ``` -To send **GlobalContext** and **LogicalThreadContext** properties in your log you need define the list of used properties in the configuration. +If you want to append **GlobalContext** and/or **LogicalThreadContext** properties to your log you need to define the list of context properties in the configuration. -For GlobalContext Properties use -`````` +For GlobalContext Properties use `` -For LogicalThreadContext Properties -`````` +For LogicalThreadContext Properties `` -You can also use **layout** with in the Config to render logs according to your Pattern Layouts - - - - - -By default, library uses Loggly /bulk end point (https://www.loggly.com/docs/http-bulk-endpoint/). To use /inputs endpoint, add the following configuration in config file. - -``` - -``` - -Set number of inner exceptions that should be sent to loggly, if you don't want the default value. -``` - +You can also use **layout** to render logs according to your Pattern Layouts +```xml + + + ``` -Add the following entry in your AssemblyInfo.cs -``` +Add the following entry to your AssemblyInfo.cs +```csharp [assembly: log4net.Config.XmlConfigurator(Watch = true)] ``` Alternatively, you can add the following code in your Main method or in Global.asax file - -``` +```csharp log4net.Config.XmlConfigurator.Configure(); ``` Create an object of the Log class using LogManager - - var logger = LogManager.GetLogger(typeof(Class)); +```csharp +var logger = LogManager.GetLogger(typeof(Class)); +``` Send logs to Loggly using the following code +```csharp +// send plain string +logger.Info("log message"); -``` - logger.Info("log message"); -``` +// send an exception +logger.Error("your log message", new Exception("your exception message")); + +// send dictionary as JSON object +var items = new Dictionary(); +items.Add("key1","value1"); +items.Add("key2", "value2"); +logger.Info(items); -For Console Application +// send any object as JSON object +logger.Debug(new { Property = "This is anonymous object", Property2 = "with two properties" }); +``` -You should add the following statement at the end of your Main method as the log4net-loggly library is asynchronous so there needs to be time for the threads the complete logging before the application exits. +## Flushing logs on application shutdown +Library is buffering and sending log messages to Loggly asynchronously in background. That means that some logs may be still in buffer when the application terminates. To make sure that all logs have been sent you need to cleanly shutdown log4net logger using following code: +```csharp +logger.Logger.Repository.Shutdown(); ``` -Console.ReadKey(); +This flushes any pending messages. + +## Advanced configuration + +Library by default serializes and sends 4 levels of inner exceptions in case of warn/error log. If you want to change this number just add following configuration to config file to `` section +```xml + ``` -### .NET Core Support: -Prerequisites: +### .NET Core Support: + +**Prerequisites:** - Since this library support .NET Core target framework 2.0, make sure you are using either version 15.3.0 or higher of Visual Studio IDE 2017 or Visual Studio Code. @@ -94,25 +101,25 @@ Console.ReadKey(); - You may also have to install the .NET Core cross-platform development workload (in the Other Toolsets section). Please see the more details [here](https://docs.microsoft.com/en-us/dotnet/core/windows-prerequisites?tabs=netcore2x). -Once you are done with the environment setup, now you are all set to create your application in .NET Core target framework 2.0. Please follow the points below- +Once you are done with the environment setup, now you are all set to create your application in .NET Core 2.0. Please follow the points below. -- If you are using Visual Studio 2017 IDE then you can create a new .NET Core project by selecting New Project from File menu. +- If you are using **Visual Studio 2017 IDE** then you can create a new .NET Core project by selecting **New Project** from **File** menu. -- Visual Studio Code users can create a new project by running the below command on the project workspace terminal- +- **Visual Studio Code** users can create a new project by running the below command on the project workspace terminal- ``` dotnet new console -o Application_Name ``` -The dotnet command creates a new application of type console for you. The -o parameter creates a directory named where your app is stored, and populates it with the required files. +The **dotnet** command creates a new application of type **console** for you. The **-o** parameter creates a directory named **Application_Name** where your app is stored, and populates it with the required files. -- If you are using Visual Studio 2017 IDE then you have to install the package log4net-loggly into your project from NuGet by running the command on Package Manager Console as shown below- +- If you are using **Visual Studio 2017 IDE** then you have to install the package **log4net-loggly** into your project from **NuGet** by running the command on **Package Manager Console** as shown below- ``` Install-Package log4net-loggly ``` -- If you are using Visual Studio Code then run the below command on the terminal to install the log4net-loggly package. +- If you are using **Visual Studio Code** then run the below command on the terminal to install the **log4net-loggly** package. ``` dotnet add package log4net-loggly @@ -120,11 +127,11 @@ dotnet add package log4net-loggly - Now when you create an applicaton in .NET Core, there is no App.config file exist already in the project so you have to create one. - (a) For Visual Studio 2017 users, you should right click on your project and create a Application Configuration File "App.config" on the root level of your project. + (a) For **Visual Studio 2017** users, you should right click on your project and create a **Application Configuration File** "App.config" on the root level of your project. - (b) For Visual Studio Code users, you should simply create the same configuration file on the the folder structure where your another files exists. + (b) For **Visual Studio Code** users, you should simply create the same configuration file on the the folder structure where your another files exists. -- You should simply add the below configuration code in your App.config file to configure LogglyAppender in your application. Make sure the configSections block is the first element of the configuration in app.config. This is a requirement set by .NET. +- You should simply add the below configuration code in your App.config file to configure LogglyAppender in your application. Make sure the **configSections** block is the first element of the configuration in app.config. This is a requirement set by .NET. ```xml @@ -139,8 +146,8 @@ dotnet add package log4net-loggly - - + + @@ -148,15 +155,15 @@ dotnet add package log4net-loggly ``` -Note: If you are using Visual Studio 2017 IDE then your application will not be able to read configurations from this App.config file until you do the following- +**Note: If you are using Visual Studio 2017 IDE then your application will not be able to read configurations from this App.config file until you do the following-** -- Right click on your App.config file from Solution Explorer, go to Properties and select the Copy to Output Directory to Copy always, click Apply and hit the OK button. +- Right click on your **App.config** file from Solution Explorer, go to **Properties** and select the **Copy to Output Directory** to **Copy always**, click Apply and hit the OK button. - If you are using Visual Studio Code then you don't need to do the extra settings for App.config file. + If you are using **Visual Studio Code** then you don't need to do the extra settings for App.config file. - As compare to .NET Frameworks, in .NET Core you don't need any AssemblyInfo.cs file to add the below code in- -``` +```csharp [assembly: log4net.Config.XmlConfigurator(Watch = true)] ``` @@ -164,45 +171,18 @@ The above code line allows the application to read the configuration from App.co - Add the following code inside the main method of your application file i.e. Program.cs- -``` +```csharp var logRepository = LogManager.GetRepository(Assembly.GetEntryAssembly()); log4net.Config.XmlConfigurator.Configure(logRepository, new FileInfo("App.config")); ``` -After adding the above code you can simply create an object of the Log class using LogManager and start logging any plaintext, exceptions, or JSON events as shown below- - -``` -var logger = LogManager.GetLogger(typeof(Class)); -//Send plaintext -logger.Info("your log message"); - -//Send an exception -logger.Error("your log message", new Exception("your exception message")); -//Send a JSON object -var items = new Dictionary(); -items.Add("key1","value1"); -items.Add("key2", "value2"); -logger.Info(items); -``` -Running the application in Visual Studio 2017 IDE is easy since you just need to click on the Start button to run your application. +Running the application in **Visual Studio 2017 IDE** is easy since you just need to click on the **Start** button to run your application. -If you are using Visual Studio Code then you have to run the below command on the terminal to run your .NET Core application- +If you are using **Visual Studio Code** then you have to run the below command on the terminal to run your .NET Core application- ``` dotnet run ``` -And that's it. After doing this, you will see your .NET Core application logs flowing into Loggly. - - -Added handling for LoggingEvent properties - -Support for properties tied to a specific event and not a ThreadContext which is shared across the entire thread. - -Added test cases project - -- Added unit test cases project in library to test consistency for new feature. - -- User can select test cases project in Visual Studio and can simply run all test cases from Test Explorer. - +And that's it. After doing this, you will see your .NET Core application logs flowing into Loggly. \ No newline at end of file diff --git a/source/log4net-loggly-console/App.config b/source/log4net-loggly-console/App.config index 12d32e3..ca4d9a2 100644 --- a/source/log4net-loggly-console/App.config +++ b/source/log4net-loggly-console/App.config @@ -16,6 +16,9 @@ + diff --git a/source/log4net-loggly-console/Program.cs b/source/log4net-loggly-console/Program.cs index 5d8e41a..56ac300 100644 --- a/source/log4net-loggly-console/Program.cs +++ b/source/log4net-loggly-console/Program.cs @@ -27,8 +27,9 @@ static void Main(string[] argArray) { GlobalContext.Properties["GlobalContextPropertySample"] = new GlobalContextTest(); + var currentFileName = Path.GetFileName(Assembly.GetExecutingAssembly().Location); var logRepository = LogManager.GetRepository(Assembly.GetEntryAssembly()); - log4net.Config.XmlConfigurator.Configure(logRepository,new FileInfo("app.config")); + log4net.Config.XmlConfigurator.Configure(logRepository, new FileInfo(currentFileName + ".config")); var log = LogManager.GetLogger(typeof(Program)); @@ -88,7 +89,11 @@ static void Main(string[] argArray) parent.Children = new List { child1, child2 }; log.Info(parent); - log.Debug("zzzz"); + log.Debug(@"This +is +some +multiline +log"); log.InfoFormat("Loggly is the best {0} to collect Logs.", "service"); log.Info(new { type1 = "newcustomtype", value1 = "newcustomvalue" }); log.Info(new TestObject()); @@ -124,7 +129,8 @@ static void Main(string[] argArray) log.Error("Exception", e); } - Console.ReadKey(); + log.Info("This is the last message. Program will terminate now."); + log.Logger.Repository.Shutdown(); } } } diff --git a/source/log4net-loggly-stress-tool/App.config b/source/log4net-loggly-stress-tool/App.config new file mode 100644 index 0000000..d3b47fc --- /dev/null +++ b/source/log4net-loggly-stress-tool/App.config @@ -0,0 +1,16 @@ + + + +
+ + + + + + + + + + + + \ No newline at end of file diff --git a/source/log4net-loggly-stress-tool/CommandLineArgs.cs b/source/log4net-loggly-stress-tool/CommandLineArgs.cs new file mode 100644 index 0000000..de2ca6e --- /dev/null +++ b/source/log4net-loggly-stress-tool/CommandLineArgs.cs @@ -0,0 +1,95 @@ +using System; + +namespace log4net_loggly_stress_tool +{ + internal class CommandLineArgs + { + public int NumEvents { get; private set; } = 1000; + public int NumLoggingThreads { get; private set; } = 1; + public int ExceptionFrequency { get; private set; } = 0; + public TimeSpan SendDelay { get; private set; } = TimeSpan.Zero; + public int LogsPerSecond { get; set; } = 0; + + public static CommandLineArgs Parse(string[] args) + { + var result = new CommandLineArgs(); + + try + { + for (int i = 0; i < args.Length; i++) + { + switch (args[i]) + { + case "-n": + case "--num-events": + i++; + result.NumEvents = int.Parse(args[i]); + if (result.NumEvents < 1) + throw new ArgumentException("Number of events must be >= 1"); + break; + case "-t": + case "--num-threads": + i++; + result.NumLoggingThreads = int.Parse(args[i]); + if (result.NumLoggingThreads < 1) + throw new ArgumentException("Number of threads must be >= 1"); + break; + case "-d": + case "--send-delay": + { + i++; + var value = int.Parse(args[i]); + if (value < 0) + throw new ArgumentException("Delay must be >= 0"); + result.SendDelay = TimeSpan.FromMilliseconds(value); + } + break; + case "-l": + case "--logs-per-second": + { + i++; + var value = int.Parse(args[i]); + if (value <= 0) + throw new ArgumentException("Logs-per-second must be > 0"); + result.LogsPerSecond = value; + } + break; + case "-e": + case "--exception-every": + i++; + result.ExceptionFrequency = int.Parse(args[i]); + if (result.ExceptionFrequency < 0) + throw new ArgumentException("Exception frequency must be >= 0"); + break; + default: + PrintHelp(); + break; + } + } + } + catch (Exception e) + { + PrintHelp(); + } + + return result; + } + + private static void PrintHelp() + { + Console.WriteLine(@" +Loggly log4net logger stress testing tool. +Tool is generating log messages in one or more threads and logs them to logger. +Fake HTTP layer is used to fake sending data to Loggly, no data are really sent out. + +Usage: log4net-loggly-stress-tool.exe [-n|--num-threads ] [-d|--send-delay ] [-e|--exception-every ] + -n|--num-events - Number of events to send. Must be > 0. Default: 1000 + -l|--logs-per-second - How many logs per second should be generated. Total number is still defined by -n, this value just slows down the generator to given frequency. + -t|--num-threads - Number of threads used to generate logs. Must be > 0. Default: 1. + -d|--send-delay - Delay for one simulated send to Loggly servers in milliseconds. Must be >= 0. Default: 0 + -e|--exception-every - Log error with exception every N logs. Must be >= 0. Default: 0 - never"); + + Environment.Exit(0); + } + } +} \ No newline at end of file diff --git a/source/log4net-loggly-stress-tool/Program.cs b/source/log4net-loggly-stress-tool/Program.cs new file mode 100644 index 0000000..36908ae --- /dev/null +++ b/source/log4net-loggly-stress-tool/Program.cs @@ -0,0 +1,137 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Reflection; +using System.Threading; +using System.Threading.Tasks; +using log4net; +using log4net.loggly; + +namespace log4net_loggly_stress_tool +{ + public class Program + { + private static ILog _log; + + private static long _count = 0; + + public static void Main(string[] args) + { + var commandLine = CommandLineArgs.Parse(args); + + // use test HTTP layer + LogglyClient.WebRequestFactory = (config, url) => new TestHttpClient(commandLine.SendDelay); + + var logRepository = LogManager.GetRepository(Assembly.GetEntryAssembly()); + log4net.Config.XmlConfigurator.Configure(logRepository); + + _log = LogManager.GetLogger(typeof(Program)); + + SetupThreadContext(); + + var exception = GetTestException(); + + Console.WriteLine("Running test in {0} threads with {1} ms delay for send and exception every {2} messages.", + commandLine.NumLoggingThreads, commandLine.SendDelay, commandLine.ExceptionFrequency); + + var watch = Stopwatch.StartNew(); + var tasks = new List(commandLine.NumLoggingThreads); + int logsPerSecondPerThread = (int)Math.Ceiling((double)commandLine.LogsPerSecond / commandLine.NumLoggingThreads); + for (int i = 0; i < commandLine.NumLoggingThreads; i++) + { + tasks.Add(Task.Factory.StartNew(() => SendContinuously(commandLine, exception, logsPerSecondPerThread), TaskCreationOptions.LongRunning)); + } + + Task.WaitAll(tasks.ToArray()); + + watch.Stop(); + + Console.WriteLine("Test finished. Elapsed: {0}, Throughput: {1} logs/s", watch.Elapsed, _count*1000 / watch.Elapsed.TotalMilliseconds); + Console.WriteLine("Press any key to exit..."); + Console.ReadKey(); + } + + private static void SendContinuously(CommandLineArgs commandLine, Exception exception, int logsPerSecond) + { + long currentCount; + Stopwatch watch = Stopwatch.StartNew(); + int countThisSecond = 0; + while ((currentCount = Interlocked.Increment(ref _count)) <= commandLine.NumEvents) + { + if (currentCount % 1000 == 0) + { + Console.WriteLine("Sent: {0}", currentCount); + } + + if (commandLine.ExceptionFrequency > 0 && currentCount % commandLine.ExceptionFrequency == 0) + { + _log.Error( + $"Test message {currentCount} Lorem ipsum dolor sit amet, consectetur adipiscing elit. Phasellus fermentum ligula " + + "et ante tincidunt venenatis. Ut pretium, mi laoreet fringilla egestas, mauris quam lacinia dolor, " + + "eu maximus nisi mauris vel lorem. Duis a ex eu orci consectetur congue sed sit amet ligula. " + + "Aenean congue mollis quam volutpat varius.", exception); + } + else + { + _log.Info( + $"Test message {currentCount}. Lorem ipsum dolor sit amet, consectetur adipiscing elit. Phasellus fermentum ligula " + + "et ante tincidunt venenatis. Ut pretium, mi laoreet fringilla egestas, mauris quam lacinia dolor, " + + "eu maximus nisi mauris vel lorem. Duis a ex eu orci consectetur congue sed sit amet ligula. " + + "Aenean congue mollis quam volutpat varius."); + } + + // if rate limiting is applied then sleep remainder of the current second before moving on + if (logsPerSecond > 0 && ++countThisSecond >= logsPerSecond) + { + Thread.Sleep(1000 - Math.Min(1000, (int)watch.ElapsedMilliseconds)); + countThisSecond = 0; + watch.Restart(); + } + } + } + + + private static Exception GetTestException() + { + Exception exception; + try + { + try + { + throw new ArgumentException("inner exception"); + } + catch (Exception e) + { + throw new InvalidOperationException("outer exception", e); + } + } + catch (Exception e) + { + exception = e; + } + + return exception; + } + + private static void SetupThreadContext() + { + ThreadContext.Properties["ThreadProperty1"] = DateTime.Now; + ThreadContext.Properties["ThreadProperty2"] = new TestClass + { + IntProperty = 123, + StringProperty = + "Lorem ipsum dolor sit amet, consectetur adipiscing elit. Phasellus fermentum ligula et ante tincidunt venenatis. " + + "Ut pretium, mi laoreet fringilla egestas, mauris quam lacinia dolor, eu maximus nisi mauris vel lorem. " + + "Duis a ex eu orci consectetur congue sed sit amet ligula. Aenean congue mollis quam volutpat varius.", + DatetimeProperty = DateTime.Now + }; + } + + private class TestClass + { + public int IntProperty { get; set; } + public string StringProperty { get; set; } + public DateTime DatetimeProperty { get; set; } + } + } +} diff --git a/source/log4net-loggly-stress-tool/TestHttpClient.cs b/source/log4net-loggly-stress-tool/TestHttpClient.cs new file mode 100644 index 0000000..15104c2 --- /dev/null +++ b/source/log4net-loggly-stress-tool/TestHttpClient.cs @@ -0,0 +1,32 @@ +using System; +using System.IO; +using System.Net; +using System.Threading; + +namespace log4net_loggly_stress_tool +{ + internal class TestHttpClient : WebRequest + { + private readonly TimeSpan _sendDelay; + + public TestHttpClient(TimeSpan sendDelay) + { + _sendDelay = sendDelay; + } + + public override WebResponse GetResponse() + { + Thread.Sleep(_sendDelay); + return new TestResponse(); + } + + public override Stream GetRequestStream() + { + return new MemoryStream(); + } + + private class TestResponse : WebResponse + { + } + } +} \ No newline at end of file diff --git a/source/log4net-loggly-stress-tool/log4net-loggly-stress-tool.csproj b/source/log4net-loggly-stress-tool/log4net-loggly-stress-tool.csproj new file mode 100644 index 0000000..2b0ba9f --- /dev/null +++ b/source/log4net-loggly-stress-tool/log4net-loggly-stress-tool.csproj @@ -0,0 +1,17 @@ + + + + Exe + net45 + log4net_loggly_stress_tool + + + + + + + + + + + diff --git a/source/log4net-loggly.UnitTests/App.config b/source/log4net-loggly.UnitTests/App.config new file mode 100644 index 0000000..2630ca5 --- /dev/null +++ b/source/log4net-loggly.UnitTests/App.config @@ -0,0 +1,22 @@ + + + +
+ + + + + + + + + + + + + + + + + + \ No newline at end of file diff --git a/source/log4net-loggly.UnitTests/IntegrationTest.cs b/source/log4net-loggly.UnitTests/IntegrationTest.cs new file mode 100644 index 0000000..278b09b --- /dev/null +++ b/source/log4net-loggly.UnitTests/IntegrationTest.cs @@ -0,0 +1,559 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Diagnostics.CodeAnalysis; +using System.IO; +using System.Net; +using System.Reflection; +using System.Text; +using System.Threading; +using FluentAssertions; +using FluentAssertions.Json; +using JetBrains.Annotations; +using log4net; +using log4net.Core; +using log4net.loggly; +using log4net.Util; +using Moq; +using Newtonsoft.Json.Linq; +using Xunit; +// ReSharper disable UnusedAutoPropertyAccessor.Local + +namespace log4net_loggly.UnitTests +{ + [UsedImplicitly] + [SuppressMessage("ReSharper", "StringLiteralTypo")] + public abstract class IntegrationTest + { + protected internal const string TestThreadName = "MyTestThread"; + + private readonly ManualResetEvent _messageSent; + protected ILog _log; + protected readonly LogglyAppender _logglyAppender; + private readonly MemoryStream _messageStream; + + protected IntegrationTest() + { + // setup HTTP client mock so that we can wait for sent message and inspect it + _messageSent = new ManualResetEvent(false); + + _messageStream = new MemoryStream(); + var webRequestMock = new Mock(); + webRequestMock.Setup(x => x.GetRequestStream()).Returns(_messageStream); + webRequestMock.Setup(x => x.GetResponse()) + .Returns(() => + { + _messageSent.Set(); + return Mock.Of(); + }); + + // use mocked web request + LogglyClient.WebRequestFactory = (config, url) => webRequestMock.Object; + + var logRepository = LogManager.GetRepository(Assembly.GetEntryAssembly()); + var currentFileName = Path.GetFileName(Assembly.GetExecutingAssembly().Location); + log4net.Config.XmlConfigurator.Configure(logRepository, new FileInfo(currentFileName + ".config")); + + _log = LogManager.GetLogger(GetType()); + + var appenders = logRepository.GetAppenders(); + _logglyAppender = (LogglyAppender)appenders[0]; + + ThreadContext.Properties.Clear(); + LogicalThreadContext.Properties.Clear(); + GlobalContext.Properties.Clear(); + + // thread name can be set just once so we need this safeguard + if (string.IsNullOrEmpty(Thread.CurrentThread.Name)) + { + Thread.CurrentThread.Name = TestThreadName; + } + } + + [Fact] + public void LogContainsThreadName() + { + _log.Info("test message"); + + var message = WaitForSentMessage(); + message.ThreadName.Should().Be(TestThreadName); + } + + [Fact] + public void LogContainsHostName() + { + _log.Info("test message"); + + var message = WaitForSentMessage(); + message.Hostname.Should().Be(Environment.MachineName); + } + + [Fact] + public void LogContainsLoggerName() + { + _log = LogManager.GetLogger(Assembly.GetExecutingAssembly(), "MyTestLogger"); + _log.Info("test message"); + + var message = WaitForSentMessage(); + message.LoggerName.Should().Be("MyTestLogger"); + } + + [Fact] + public void LogContainsProcessName() + { + _log.Info("test message"); + + var message = WaitForSentMessage(); + message.Process.Should().Be(Process.GetCurrentProcess().ProcessName); + } + + [Fact] + public void LogContainsTimestampInLocalTime() + { + _log.Info("test message"); + + var message = WaitForSentMessage(); + var timestamp = DateTime.Parse(message.Timestamp); + timestamp.Should().BeWithin(TimeSpan.FromSeconds(5)).Before(DateTime.Now); + } + + [Theory] + [MemberData(nameof(LogLevels))] + public void LogContainsLogLevel(Level level) + { + _log.Logger.Log(GetType(), level, "test message", null); + + var message = WaitForSentMessage(); + message.Level.Should().Be(level.Name); + } + + [Fact] + public void LogContainsPassedException() + { + Exception thrownException; + try + { + throw new InvalidOperationException("test exception"); + } + catch (Exception e) + { + thrownException = e; + _log.Error("test message", e); + } + + var message = WaitForSentMessage(); + var exception = message.ExtraProperties.Should().HaveElement("exception", "logged exception should be in the data").Which; + AssertException(exception, thrownException); + } + + [Fact] + public void LogContainsInnerException() + { + Exception thrownException; + try + { + try + { + throw new ArgumentException("inner exception"); + } + catch (Exception e) + { + throw new InvalidOperationException("test exception", e); + } + } + catch (Exception e) + { + thrownException = e; + _log.Error("test message", e); + } + + var message = WaitForSentMessage(); + var exception = message.ExtraProperties.Should().HaveElement("exception", "logged exception should be in the data").Which; + AssertException(exception, thrownException); + AssertException(exception["innerException"], thrownException.InnerException); + } + + [Fact] + public void LogContainsEventContextProperties() + { + var expectedJson = @" +{ +""MyProperty1"": ""MyValue1"", +""MyProperty2"": { + ""StringProperty"": ""test string"", + ""IntProperty"": 123, + ""Parent"": null + } +}"; + var data = new LoggingEventData + { + Level = Level.Info, + Message = "test message", + Properties = new PropertiesDictionary() + }; + data.Properties["MyProperty1"] = "MyValue1"; + data.Properties["MyProperty2"] = new TestItem { IntProperty = 123, StringProperty = "test string" }; + + _log.Logger.Log(new LoggingEvent(data)); + + var message = WaitForSentMessage(); + message.ExtraProperties.Should().BeEquivalentTo(JObject.Parse(expectedJson)); + } + + [Fact] + public void LogContainsThreadContextProperties() + { + ThreadContext.Properties["MyProperty1"] = "MyValue1"; + ThreadContext.Properties["MyProperty2"] = new TestItem { IntProperty = 123, StringProperty = "test string" }; + var expectedJson = @" +{ +""MyProperty1"": ""MyValue1"", +""MyProperty2"": { + ""StringProperty"": ""test string"", + ""IntProperty"": 123, + ""Parent"": null + } +}"; + + _log.Info("test message"); + + var message = WaitForSentMessage(); + message.ExtraProperties.Should().BeEquivalentTo(JObject.Parse(expectedJson)); + } + + [Fact] + public void LogContainsSelectedLogicalThreadContextProperties() + { + LogicalThreadContext.Properties["lkey1"] = "MyValue1"; + LogicalThreadContext.Properties["lkey2"] = new TestItem { IntProperty = 123, StringProperty = "test string" }; + LogicalThreadContext.Properties["lkey3"] = "this won't be in the log"; + // only properties defines in app.config in will be included + var expectedJson = @" +{ +""lkey1"": ""MyValue1"", +""lkey2"": { + ""StringProperty"": ""test string"", + ""IntProperty"": 123, + ""Parent"": null + } +}"; + + _log.Info("test message"); + + var message = WaitForSentMessage(); + message.ExtraProperties.Should().BeEquivalentTo(JObject.Parse(expectedJson)); + } + + [Fact] + public void LogContainsSelectedGlobalContextProperties() + { + GlobalContext.Properties["gkey1"] = "MyValue1"; + GlobalContext.Properties["gkey2"] = new TestItem { IntProperty = 123, StringProperty = "test string" }; + GlobalContext.Properties["gkey3"] = "this won't be in the log"; + // only properties defines in app.config in will be included + var expectedJson = @" +{ +""gkey1"": ""MyValue1"", +""gkey2"": { + ""StringProperty"": ""test string"", + ""IntProperty"": 123, + ""Parent"": null + } +}"; + + _log.Info("test message"); + + var message = WaitForSentMessage(); + message.ExtraProperties.Should().BeEquivalentTo(JObject.Parse(expectedJson)); + } + + [Fact] + public void LogContainsThreadContextStacks() + { + using (ThreadContext.Stacks["TestStack1"].Push("TestStackValue1")) + { + using (ThreadContext.Stacks["TestStack2"].Push("TestStackValue2")) + using (ThreadContext.Stacks["TestStack1"].Push("TestStackValue3")) + { + _log.Info("test message"); + } + } + var expectedJson = @" +{ +""TestStack1"": ""TestStackValue1 TestStackValue3"", +""TestStack2"": ""TestStackValue2"" +}"; + + var message = WaitForSentMessage(); + message.ExtraProperties.Should().BeEquivalentTo(JObject.Parse(expectedJson)); + } + + [Fact] + public void LogContainsLogicalThreadContextStacks() + { + using (LogicalThreadContext.Stacks["lkey1"].Push("TestStackValue1")) + { + using (LogicalThreadContext.Stacks["lkey2"].Push("TestStackValue2")) + using (LogicalThreadContext.Stacks["lkey1"].Push("TestStackValue3")) + { + _log.Info("test message"); + } + } + var expectedJson = @" +{ +""lkey1"": ""TestStackValue1 TestStackValue3"", +""lkey2"": ""TestStackValue2"" +}"; + + var message = WaitForSentMessage(); + message.ExtraProperties.Should().BeEquivalentTo(JObject.Parse(expectedJson)); + } + + [Fact] + public void EventContextHasHighestPriority() + { + GlobalContext.Properties["CommonProperty"] = "GlobalContext"; + ThreadContext.Properties["CommonProperty"] = "ThreadContext"; + LogicalThreadContext.Properties["CommonProperty"] = "LogicalThreadContext"; + var data = new LoggingEventData + { + Level = Level.Info, + Message = "test message", + Properties = new PropertiesDictionary() + }; + data.Properties["CommonProperty"] = "EventContext"; + _log.Logger.Log(new LoggingEvent(data)); + + var message = WaitForSentMessage(); + message.ExtraProperties.Should().HaveElement("CommonProperty") + .Which.Value().Should().Be("EventContext"); + } + + [Fact] + public void LogicalThreadContextHasSecondHighestPriority() + { + GlobalContext.Properties["CommonProperty"] = "GlobalContext"; + ThreadContext.Properties["CommonProperty"] = "ThreadContext"; + LogicalThreadContext.Properties["CommonProperty"] = "LogicalThreadContext"; + // no event properties here + + _log.Info("test message"); + + var message = WaitForSentMessage(); + message.ExtraProperties.Should().HaveElement("CommonProperty") + .Which.Value().Should().Be("LogicalThreadContext"); + } + + [Fact] + public void ThreadContextHaveThirdHighestPriority() + { + GlobalContext.Properties["CommonProperty"] = "GlobalContext"; + ThreadContext.Properties["CommonProperty"] = "ThreadContext"; + // no event or logical thread context properties here + + _log.Info("test message"); + + var message = WaitForSentMessage(); + message.ExtraProperties.Should().HaveElement("CommonProperty") + .Which.Value().Should().Be("ThreadContext"); + } + + [Fact] + public void PropertiesFromDifferentContextsAreMerged() + { + GlobalContext.Properties["gkey1"] = "GlobalContext"; + ThreadContext.Properties["tkey1"] = "ThreadContext"; + LogicalThreadContext.Properties["lkey1"] = "LogicalThreadContext"; + var data = new LoggingEventData + { + Level = Level.Info, + Message = "test message", + Properties = new PropertiesDictionary() + }; + data.Properties["ekey1"] = "EventContext"; + var expectedJson = @" +{ +""gkey1"": ""GlobalContext"", +""tkey1"": ""ThreadContext"", +""lkey1"": ""LogicalThreadContext"", +""ekey1"": ""EventContext"", +}"; + + _log.Logger.Log(new LoggingEvent(data)); + + var message = WaitForSentMessage(); + message.ExtraProperties.Should().BeEquivalentTo(JObject.Parse(expectedJson)); + } + + [Fact] + public void SendPlainString_DoesNotHaveAnyExtraProperties() + { + _log.Info("test message"); + + var message = WaitForSentMessage(); + message.ExtraProperties.Should().HaveCount(0); + } + + [Fact] + public void SendObject_SendsItAsJson() + { + var expectedJson = @" +{ + ""StringProperty"": ""test string"", + ""IntProperty"": 123, + ""Parent"": null +}"; + var item = new TestItem { StringProperty = "test string", IntProperty = 123 }; + _log.Info(item); + var message = WaitForSentMessage(); + + message.ExtraProperties.Should().BeEquivalentTo(JObject.Parse(expectedJson)); + } + + [Fact] + public void SendAnonymousObject_SendsItAsJson() + { + var expectedJson = @" +{ + ""StringProperty"": ""test string"", + ""IntProperty"": 123 +}"; + _log.Info(new { StringProperty = "test string", IntProperty = 123 }); + var message = WaitForSentMessage(); + + message.ExtraProperties.Should().BeEquivalentTo(JObject.Parse(expectedJson)); + } + + [Fact] + public void SendNestedObjects_SendsItAsJson() + { + var expectedJson = @" +{ + ""ParentStringProperty"": ""parent"", + ""Child"": { + ""StringProperty"": ""test string"", + ""IntProperty"": 123 + } +}"; + var item = new TestItem { StringProperty = "test string", IntProperty = 123 }; + var parent = new TestParentItem { ParentStringProperty = "parent", Child = item }; + item.Parent = parent; + _log.Info(parent); + var message = WaitForSentMessage(); + + message.ExtraProperties.Should().BeEquivalentTo(JObject.Parse(expectedJson)); + } + + [Fact] + public void SendJsonString_SendsItAsJson() + { + var expectedJson = @" +{ + ""StringProperty"": ""test string"", + ""IntProperty"": 123 +}"; + + _log.Info("{\"StringProperty\": \"test string\", \"IntProperty\": 123}"); + + var message = WaitForSentMessage(); + message.ExtraProperties.Should().BeEquivalentTo(JObject.Parse(expectedJson)); + } + + [Fact] + public void LogContainsFixedValues() + { + ThreadContext.Properties["TestFixValue"] = new TestFixingItem(); + _log.Info("test message"); + + var message = WaitForSentMessage(); + // TestFixingItem returns "volatile value" on ToString() but "fixed value" on GetFixedObject() + message.ExtraProperties["TestFixValue"].Should().HaveValue("fixed value", "type of this value requires fixing"); + } + + protected SentMessage WaitForSentMessage() + { + _messageSent.WaitOne(TimeSpan.FromSeconds(10)).Should().BeTrue("Log message should have been sent already."); + var message = Encoding.UTF8.GetString(_messageStream.ToArray()); + return new SentMessage(message); + } + + private void AssertException(JToken exception, Exception expectedException) + { + exception.Value("exceptionType").Should() + .Be(expectedException.GetType().FullName, "exception type should be correct"); + exception.Value("exceptionMessage").Should().Be(expectedException.Message, "exception message should be correct"); + exception.Value("stacktrace").Should().Contain(expectedException.StackTrace, "exception stack trace should be correct"); + } + + public static IEnumerable LogLevels => + new[] + { + new[] {Level.Debug}, + new[] {Level.Info}, + new[] {Level.Warn}, + new[] {Level.Error} + }; + + protected class SentMessage + { + public SentMessage(string json) + { + OriginalJson = json; + var jsonObject = JObject.Parse(json); + Timestamp = jsonObject["timestamp"].Value(); + jsonObject.Remove("timestamp"); + Level = jsonObject["level"].Value(); + jsonObject.Remove("level"); + Hostname = jsonObject["hostName"].Value(); + jsonObject.Remove("hostName"); + Process = jsonObject["process"].Value(); + jsonObject.Remove("process"); + ThreadName = jsonObject["threadName"].Value(); + jsonObject.Remove("threadName"); + LoggerName = jsonObject["loggerName"].Value(); + jsonObject.Remove("loggerName"); + Message = jsonObject["message"]?.Value(); + jsonObject.Remove("message"); + // anything that is dynamic goes as whole remaining JSON object to special property + ExtraProperties = jsonObject; + } + + public string OriginalJson { get; } + public string Timestamp { get; } + public string Level { get; } + public string Hostname { get; } + public string Process { get; } + public string ThreadName { get; } + public string LoggerName { get; } + public string Message { get; } + public JObject ExtraProperties { get; } + } + + private class TestItem + { + public string StringProperty { get; set; } + public int IntProperty { get; set; } + public TestParentItem Parent { get; set; } + } + + private class TestParentItem + { + public string ParentStringProperty { get; set; } + public TestItem Child { get; set; } + } + + private class TestFixingItem : IFixingRequired + { + public object GetFixedObject() + { + return "fixed value"; + } + + public override string ToString() + { + return "volatile value"; + } + } + + } +} diff --git a/source/log4net-loggly.UnitTests/IntegrationTestWithLayout.cs b/source/log4net-loggly.UnitTests/IntegrationTestWithLayout.cs new file mode 100644 index 0000000..0d86f15 --- /dev/null +++ b/source/log4net-loggly.UnitTests/IntegrationTestWithLayout.cs @@ -0,0 +1,41 @@ +using FluentAssertions; +using log4net.Layout; +using Xunit; + +namespace log4net_loggly.UnitTests +{ + public class IntegrationTestWithLayout : IntegrationTest + { + public IntegrationTestWithLayout() + { + _logglyAppender.Layout = new PatternLayout("[%thread] %level - %message"); + } + + [Fact] + public void LogContainsMessageFormattedByLayout() + { + _log.Info("test message"); + + var message = WaitForSentMessage(); + message.Message.Should().Be($"[{TestThreadName}] INFO - test message"); + } + + [Fact] + public void SendFormattedString_SendsItProperlyFormatted() + { + _log.InfoFormat("Test message: {0:D2}", 3); + + var message = WaitForSentMessage(); + message.Message.Should().Be($"[{TestThreadName}] INFO - Test message: 03"); + } + + [Fact] + public void SendNull_DoesNotPutNullToFormattedString() + { + _log.Info(null); + + var message = WaitForSentMessage(); + message.Message.Should().Be($"[{TestThreadName}] INFO - "); + } + } +} \ No newline at end of file diff --git a/source/log4net-loggly.UnitTests/IntegrationTestWithoutLayout.cs b/source/log4net-loggly.UnitTests/IntegrationTestWithoutLayout.cs new file mode 100644 index 0000000..6154311 --- /dev/null +++ b/source/log4net-loggly.UnitTests/IntegrationTestWithoutLayout.cs @@ -0,0 +1,40 @@ +using FluentAssertions; +using Xunit; + +namespace log4net_loggly.UnitTests +{ + public class IntegrationTestWithoutLayout : IntegrationTest + { + public IntegrationTestWithoutLayout() + { + _logglyAppender.Layout = null; + } + + [Fact] + public void LogContainsMessageAsIs() + { + _log.Info("test message"); + + var message = WaitForSentMessage(); + message.Message.Should().Be("test message"); + } + + [Fact] + public void SendFormattedString_SendsItProperlyFormatted() + { + _log.InfoFormat("Test message: {0:D2}", 3); + + var message = WaitForSentMessage(); + message.Message.Should().Be("Test message: 03"); + } + + [Fact] + public void SendNull_SendsNullString() + { + _log.Info(null); + + var message = WaitForSentMessage(); + message.Message.Should().Be("null"); + } + } +} \ No newline at end of file diff --git a/source/log4net-loggly.UnitTests/LogglyAppenderTest.cs b/source/log4net-loggly.UnitTests/LogglyAppenderTest.cs new file mode 100644 index 0000000..147e604 --- /dev/null +++ b/source/log4net-loggly.UnitTests/LogglyAppenderTest.cs @@ -0,0 +1,77 @@ +using System; +using FluentAssertions; +using log4net.Core; +using log4net.loggly; +using Moq; +using Xunit; + +namespace log4net_loggly.UnitTests +{ + public class LogglyAppenderTest + { + [Fact] + public void Append_BuffersMessageToBeSent() + { + var formatterMock = new Mock(); + formatterMock.Setup(x => x.ToJson(It.IsAny(), It.IsAny())) + .Returns((e, m) => $"Formatted: {e.RenderedMessage}"); + var bufferMock = new Mock(); + + var appender = new LogglyAppender(new Config(), formatterMock.Object, bufferMock.Object); + + var evt = new LoggingEvent(new LoggingEventData + { + Message = "test log" + }); + appender.DoAppend(evt); + + bufferMock.Verify(x => x.BufferForSend("Formatted: test log"), "message wasn't enqueued to be sent"); + } + + [Fact] + public void Flush_FlushesBuffer() + { + var bufferMock = new Mock(); + bufferMock.Setup(x => x.Flush(It.IsAny())).Returns(true); + + var appender = new LogglyAppender(new Config(), Mock.Of(), bufferMock.Object); + + var result = appender.Flush(100); + + result.Should().BeTrue("flush should be successful"); + bufferMock.Verify(x => x.Flush(TimeSpan.FromMilliseconds(100))); + } + + [Fact] + public void AppenderPropertiesSetConfigurationValues() + { + var config = new Config(); + var appender = new LogglyAppender(config, Mock.Of(), Mock.Of()); + + appender.RootUrl = "root-url"; + appender.BufferSize = 123; + appender.CustomerToken = "test-token"; + appender.GlobalContextKeys = "global-keys"; + appender.LogicalThreadContextKeys = "thread-keys"; + appender.NumberOfInnerExceptions = 123; + appender.Tag = "test-tag"; + appender.SendInterval = TimeSpan.FromSeconds(123); + appender.TimeoutInSeconds = 123; + appender.UserAgent = "user-agent"; + + config.Should().BeEquivalentTo(new + { + RootUrl = "root-url", + BufferSize = 123, + CustomerToken = "test-token", + GlobalContextKeys = "global-keys", + LogicalThreadContextKeys = "thread-keys", + NumberOfInnerExceptions = 123, + Tag = "test-tag", + SendInterval = TimeSpan.FromSeconds(123), + TimeoutInSeconds = 123, + UserAgent = "user-agent" + }); + } + } +} diff --git a/source/log4net-loggly.UnitTests/LogglyAsyncBufferTest.cs b/source/log4net-loggly.UnitTests/LogglyAsyncBufferTest.cs new file mode 100644 index 0000000..815c947 --- /dev/null +++ b/source/log4net-loggly.UnitTests/LogglyAsyncBufferTest.cs @@ -0,0 +1,290 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using System.Threading; +using FluentAssertions; +using log4net.loggly; +using Moq; +using Xunit; + +namespace log4net_loggly.UnitTests +{ + public class LogglyAsyncBufferTest + { + private readonly Config _config; + private readonly Mock _clientMock; + private CountdownEvent _allSentEvent; + private readonly ManualResetEvent _allowSendingEvent; + private readonly List _sentMessages; + + private static readonly TimeSpan MaxWaitTime = TimeSpan.FromSeconds(5); + + public LogglyAsyncBufferTest() + { + _config = new Config + { + // make sure we don't send by time expiration unless explicitly set + SendInterval = TimeSpan.FromDays(1) + }; + _clientMock = new Mock(); + _sentMessages = new List(); + _allowSendingEvent = new ManualResetEvent(true); + } + + + [Fact] + public void Bulk_SendsMessagesWhenBufferSizeReached() + { + _config.BufferSize = 3; + ExpectSends(1); + var buffer = new LogglyAsyncBuffer(_config, _clientMock.Object); + + buffer.BufferForSend("test message 1"); + buffer.BufferForSend("test message 2"); + buffer.BufferForSend("test message 3"); + + _allSentEvent.Wait(MaxWaitTime).Should().BeTrue("messages should be sent"); + _sentMessages.Should().BeEquivalentTo(new[] + { + "test message 1", + "test message 2", + "test message 3" + }, "correct messages should be sent"); + } + + [Fact] + public void DoesNotSendMessagesWhenBufferIsNotFullAndTimeIsNotExpired() + { + _config.BufferSize = 3; + ExpectSends(1); + var buffer = new LogglyAsyncBuffer(_config, _clientMock.Object); + + buffer.BufferForSend("test message 1"); + buffer.BufferForSend("test message 2"); + // one message missing for full buffer + + _allSentEvent.Wait(TimeSpan.FromSeconds(3)).Should().BeFalse("messages should not be sent"); + _sentMessages.Should().BeEmpty("no messages should be sent"); + } + + [Fact] + public void SendsMessagesWhenTimeExpires() + { + _config.BufferSize = 3; + _config.SendInterval = TimeSpan.FromMilliseconds(500); + ExpectSends(1); + var buffer = new LogglyAsyncBuffer(_config, _clientMock.Object); + + buffer.BufferForSend("test message 1"); + buffer.BufferForSend("test message 2"); + // one message missing for full buffer but this time it sends by timer + + _allSentEvent.Wait(MaxWaitTime).Should().BeTrue("messages should be sent"); + _sentMessages.Should().BeEquivalentTo(new[] + { + "test message 1", + "test message 2" + }, "correct messages should be sent"); + } + + [Fact] + public void SendsAllAvailableMessages() + { + _config.BufferSize = 3; + ExpectSends(3); + var buffer = new LogglyAsyncBuffer(_config, _clientMock.Object); + + buffer.BufferForSend("test message 1"); + buffer.BufferForSend("test message 2"); + buffer.BufferForSend("test message 3"); + buffer.BufferForSend("test message 4"); + buffer.BufferForSend("test message 5"); + buffer.BufferForSend("test message 6"); + buffer.BufferForSend("test message 7"); + buffer.BufferForSend("test message 8"); + buffer.BufferForSend("test message 9"); + + _allSentEvent.Wait(MaxWaitTime).Should().BeTrue("messages should be sent"); + _sentMessages.Should().BeEquivalentTo(new[] + { + "test message 1", + "test message 2", + "test message 3", + "test message 4", + "test message 5", + "test message 6", + "test message 7", + "test message 8", + "test message 9" + }, "correct messages should be sent"); + } + + [Fact] + public void DiscardsOldestMessagesIfMaxQueueSizeIsSet() + { + _config.MaxLogQueueSize = 5; + ExpectSends(1); + var buffer = new LogglyAsyncBuffer(_config, _clientMock.Object); + + _allowSendingEvent.Reset(); // block after first message sending + buffer.BufferForSend("test message 1"); + // trigger send without waiting for full buffer + buffer.Flush(TimeSpan.FromMilliseconds(10)); + _allSentEvent.Wait(MaxWaitTime).Should().BeTrue("first message should be already sent"); + + ExpectSends(1); + + buffer.BufferForSend("test message 2"); + buffer.BufferForSend("test message 3"); + buffer.BufferForSend("test message 4"); + buffer.BufferForSend("test message 5"); + buffer.BufferForSend("test message 6"); + buffer.BufferForSend("test message 7"); + buffer.BufferForSend("test message 8"); + buffer.BufferForSend("test message 9"); + + // now allow sending the rest + _allowSendingEvent.Set(); + + _allSentEvent.Wait(MaxWaitTime).Should().BeTrue("messages should be sent"); + _sentMessages.Should().BeEquivalentTo(new[] + { + // message 1 initiated whole sending so it was sent + "test message 1", + // messages 2-4 were dropped because they exceeded buffer size when message 1 was being sent + "test message 5", + "test message 6", + "test message 7", + "test message 8", + "test message 9", + }, "correct messages should be sent"); + } + + [Fact] + public void Flush_FlushesPendingMessages() + { + _config.BufferSize = 3; + ExpectSends(1); + var buffer = new LogglyAsyncBuffer(_config, _clientMock.Object); + + buffer.BufferForSend("test message 1"); + buffer.BufferForSend("test message 2"); + + buffer.Flush(MaxWaitTime); + + _sentMessages.Should().BeEquivalentTo(new[] + { + "test message 1", + "test message 2" + }, "pending messages should be sent"); + } + + [Fact] + public void Flush_ReturnsTrueIfAllMessagesAreSent() + { + _config.BufferSize = 3; + var buffer = new LogglyAsyncBuffer(_config, _clientMock.Object); + + buffer.BufferForSend("test message 1"); + buffer.BufferForSend("test message 2"); + + var result = buffer.Flush(MaxWaitTime); + + result.Should().BeTrue(); + } + + [Fact] + public void Flush_ReturnsFalseIfNotAllMessagesAreSent() + { + _config.BufferSize = 3; + ExpectSends(1); + var buffer = new LogglyAsyncBuffer(_config, _clientMock.Object); + + // block sending + _allowSendingEvent.Reset(); + buffer.BufferForSend("test message 1"); + buffer.BufferForSend("test message 2"); + + var result = buffer.Flush(TimeSpan.FromSeconds(1)); + + result.Should().BeFalse(); + } + + + [Fact] + public void SentBulkIsLimitedByMaxBulkSize() + { + // message of 10 bytes, buffer for 10 messages = 100 bytes + // max bulk size se to 30 -> bulk size should be limited by this number + _config.MaxBulkSizeBytes = 30; + _config.BufferSize = 10; + var oneMessageSize = 10; + var oneMessage = new String('x', oneMessageSize); + + ExpectSends(1); + + var buffer = new LogglyAsyncBuffer(_config, _clientMock.Object); + + for (int i = 0; i < _config.BufferSize; i++) + { + buffer.BufferForSend(oneMessage); + } + + _allSentEvent.Wait(MaxWaitTime).Should().BeTrue("messages should be sent"); + _sentMessages.Should().BeEquivalentTo(new[] + { + oneMessage, + oneMessage, + oneMessage + }, "correct messages should be sent"); + } + + [Fact] + public void NextBulkSizeLimitationStartsFromZero() + { + // message of 10 bytes, buffer for 10 messages = 100 bytes + // max bulk size se to 30 -> bulk size should be limited by this number + _config.MaxBulkSizeBytes = 30; + _config.BufferSize = 10; + var oneMessageSize = 10; + var oneMessage = new String('x', oneMessageSize); + + ExpectSends(3); + + var buffer = new LogglyAsyncBuffer(_config, _clientMock.Object); + + // +7 messages so that 3 bulks by 3 messages are sent before number of messages goes below buffer size + for (int i = 0; i < _config.BufferSize + 7; i++) + { + buffer.BufferForSend(oneMessage); + } + + _allSentEvent.Wait(MaxWaitTime).Should().BeTrue("messages should be sent"); + + _sentMessages.Should().BeEquivalentTo(new[] + { + oneMessage, + oneMessage, + oneMessage, + oneMessage, + oneMessage, + oneMessage, + oneMessage, + oneMessage, + oneMessage, + }, "correct messages should be sent"); + } + + private void ExpectSends(int numberOfSends) + { + _allSentEvent = new CountdownEvent(numberOfSends); + _clientMock.Setup(x => x.Send(It.IsAny(), It.IsAny())) + .Callback((m,c) => + { + _sentMessages.AddRange(m.Take(c)); + _allSentEvent.Signal(); + _allowSendingEvent.WaitOne(); + }); + } + } +} diff --git a/source/log4net-loggly.UnitTests/LogglyClientTest.cs b/source/log4net-loggly.UnitTests/LogglyClientTest.cs new file mode 100644 index 0000000..0889887 --- /dev/null +++ b/source/log4net-loggly.UnitTests/LogglyClientTest.cs @@ -0,0 +1,138 @@ +using System; +using System.IO; +using System.Net; +using System.Text; +using FluentAssertions; +using log4net.loggly; +using Moq; +using Xunit; + +namespace log4net_loggly.UnitTests +{ + public class LogglyClientTest + { + private MemoryStream _messageStream; + private string _usedUrl; + private readonly Mock _webRequestMock; + + public LogglyClientTest() + { + _webRequestMock = new Mock(); + _webRequestMock.Setup(x => x.GetRequestStream()).Returns(() => + { + _messageStream = new MemoryStream(); + return _messageStream; + }); + _webRequestMock.Setup(x => x.GetResponse()) + .Returns(() => + { + return Mock.Of(); + }); + + LogglyClient.WebRequestFactory = (c, u) => + { + _usedUrl = u; + return _webRequestMock.Object; + }; + } + + [Fact] + public void SendsToProperUrl() + { + var config = new Config + { + RootUrl = "https://logs01.loggly.test", + CustomerToken = "customer-token", + Tag = "tag1,tag2", + UserAgent = "user-agent" + }; + var client = new LogglyClient(config); + + client.Send(new[] { "test message" }, 1); + + _usedUrl.Should().Be($"https://logs01.loggly.test/bulk/customer-token/tag/tag1,tag2,user-agent"); + } + + [Fact] + public void DoesNotRetrySendWhenTokenIsInvalid() + { + var forbiddenResponse = new Mock(); + forbiddenResponse.SetupGet(x => x.StatusCode).Returns(HttpStatusCode.Forbidden); + + _webRequestMock.Setup(x => x.GetResponse()) + .Throws(new WebException("test-error", null, WebExceptionStatus.ProtocolError, + forbiddenResponse.Object)); + + var client = new LogglyClient(new Config()); + + client.Send(new[] { "test message" }, 1); + + _webRequestMock.Verify(x => x.GetResponse(), Times.Once, "Invalid token should not be retried"); + } + + [Fact] + public void RetriesSendWhenErrorOccurs() + { + var notFoundResponse = new Mock(); + notFoundResponse.SetupGet(x => x.StatusCode).Returns(HttpStatusCode.NotFound); + + _webRequestMock.Setup(x => x.GetResponse()) + .Throws(new WebException("test-error", null, WebExceptionStatus.ProtocolError, + notFoundResponse.Object)); + + var config = new Config + { + MaxSendRetries = 3 + }; + var client = new LogglyClient(config); + + client.Send(new[] { "test message" }, 1); + + _webRequestMock.Verify(x => x.GetResponse(), Times.Exactly(config.MaxSendRetries + 1), + "Generic send error should be retried"); + } + + [Fact] + public void SendsCorrectData() + { + var client = new LogglyClient(new Config()); + + client.Send(new[] { "Test message to be sent" }, 1); + + var message = Encoding.UTF8.GetString(_messageStream.ToArray()); + message.Should().Be("Test message to be sent"); + } + + [Fact] + public void SendsOnlyProperPartOfMessageBuffer() + { + var client = new LogglyClient(new Config()); + + client.Send(new[] { "message 1", "message 2", "message 3" }, 2); + + var message = Encoding.UTF8.GetString(_messageStream.ToArray()); + message.Should().Be($"message 1{Environment.NewLine}message 2"); + } + + [Fact] + public void CreatesProperWebRequest() + { + var config = new Config + { + TimeoutInSeconds = 12, + UserAgent = "test-agent" + }; + var request = (HttpWebRequest)LogglyClient.CreateWebRequest(config, "http://test-url"); + + request.Should().BeEquivalentTo(new + { + Method = "POST", + ReadWriteTimeout = 12000, + Timeout = 12000, + ContentType = "application/json", + UserAgent = "test-agent", + KeepAlive = true + }, x => x.ExcludingMissingMembers()); + } + } +} diff --git a/source/log4net-loggly.UnitTests/LogglyFormatterTest.cs b/source/log4net-loggly.UnitTests/LogglyFormatterTest.cs index e2f695b..1b87000 100644 --- a/source/log4net-loggly.UnitTests/LogglyFormatterTest.cs +++ b/source/log4net-loggly.UnitTests/LogglyFormatterTest.cs @@ -1,466 +1,599 @@ -namespace log4net_loggly.UnitTests +using log4net.Util; +using System; +using System.Diagnostics; +using System.Globalization; +using System.Text.RegularExpressions; +using AutoFixture; +using FluentAssertions; +using FluentAssertions.Json; +using JetBrains.Annotations; +using log4net; +using log4net.Core; +using log4net.loggly; +using log4net.ObjectRenderer; +using log4net.Repository; +using log4net_loggly.UnitTests.Models; +using Moq; +using Newtonsoft.Json; +using Newtonsoft.Json.Linq; +using Xunit; + +namespace log4net_loggly.UnitTests { - using System; - using AutoFixture; - using FluentAssertions; - using JetBrains.Annotations; - using log4net; - using log4net.Core; - using log4net.loggly; - using log4net.Repository; - using Models; - using Moq; - using Newtonsoft.Json; - using Newtonsoft.Json.Linq; - using Xunit; - [UsedImplicitly] public class LogglyFormatterTest { - public class ToJsonMethod + private readonly Fixture _fixture; + + public LogglyFormatterTest() { - private readonly Fixture _fixture; + _fixture = new Fixture(); + _fixture.Customize(new SupportMutableValueTypesCustomization()); - public ToJsonMethod() - { - _fixture = new Fixture(); - _fixture.Customize(new SupportMutableValueTypesCustomization()); - _fixture.Customize(c => c.With(x => x.Config, _fixture.Freeze>().Object)); - } + ThreadContext.Properties.Clear(); + } - [Fact] - public void ShouldAddAHostNameProperty() - { - var evt = _fixture.Create(); - var instance = _fixture.Create(); + [Fact] + public void ShouldAddAHostNameProperty() + { + var evt = _fixture.Create(); + var instance = new LogglyFormatter(new Config()); - var result = instance.ToJson(evt); - dynamic json = JObject.Parse(result); + var result = instance.ToJson(evt, evt.RenderedMessage); + dynamic json = JObject.Parse(result); - var hostName = (string)json.hostName; + var hostName = (string)json.hostName; - hostName.Should().NotBeNullOrEmpty("because the machine name is used to set the hostname"); - } + hostName.Should().NotBeNullOrEmpty("because the machine name is used to set the hostname"); + } - [Fact] - public void ShouldAddALevelProperty() - { - var evt = _fixture.Create(); - var instance = _fixture.Create(); + [Fact] + public void ShouldAddALevelProperty() + { + var evt = _fixture.Create(); + var instance = new LogglyFormatter(new Config()); - var result = instance.ToJson(evt); - dynamic json = JObject.Parse(result); + var result = instance.ToJson(evt, evt.RenderedMessage); + dynamic json = JObject.Parse(result); - var level = (string)json.level; + var level = (string)json.level; - level.Should().StartWith("levelName", "because the level name property on the event is used"); - } + level.Should().StartWith("levelName", "because the level name property on the event is used"); + } - [Fact] - public void ShouldAddALoggerNameProperty() - { - var evt = _fixture.Create(); - var instance = _fixture.Create(); + [Fact] + public void ShouldAddALoggerNameProperty() + { + var evt = _fixture.Create(); + var instance = new LogglyFormatter(new Config()); - var result = instance.ToJson(evt); - dynamic json = JObject.Parse(result); + var result = instance.ToJson(evt, evt.RenderedMessage); + dynamic json = JObject.Parse(result); - var loggerName = (string)json.loggerName; + var loggerName = (string)json.loggerName; - loggerName.Should().StartWith("LoggerName", "because this is the value of the LoggerName property on the event"); - } + loggerName.Should().StartWith("LoggerName", "because this is the value of the LoggerName property on the event"); + } - [Fact] - public void ShouldAddAMessagePropertyForEventsWithoutMessages() - { - var evt = _fixture.Create(); - var instance = _fixture.Create(); + [Fact] + public void ShouldAddAMessagePropertyForEventsWithoutMessages() + { + var evt = new LoggingEvent(new LoggingEventData { Level = Level.Info }); + var instance = new LogglyFormatter(new Config()); - var result = instance.ToJson(evt); - dynamic json = JObject.Parse(result); + var result = instance.ToJson(evt, evt.RenderedMessage); + dynamic json = JObject.Parse(result); - var message = (string)json.message; + var message = (string)json.message; - message.Should() - .Be("null", "because the MessageObject property is null but we want to log \"null\" to show this explicitly"); - } + message.Should() + .Be("null", "because the MessageObject property is null but we want to log \"null\" to show this explicitly"); + } - [Fact] - public void ShouldAddAProcessProperty() - { - var evt = _fixture.Create(); - var instance = _fixture.Create(); + [Fact] + public void ShouldAddAProcessProperty() + { + var evt = _fixture.Create(); + var instance = new LogglyFormatter(new Config()); - var result = instance.ToJson(evt); - dynamic json = JObject.Parse(result); + var result = instance.ToJson(evt, evt.RenderedMessage); + dynamic json = JObject.Parse(result); - var process = (string)json.process; + var process = (string)json.process; - process.Should().NotBeNullOrEmpty("because the value is taken from the current process which should always be set"); - } + process.Should().NotBeNullOrEmpty("because the value is taken from the current process which should always be set"); + } - [Fact] - public void ShouldAddAThreadNameProperty() - { - var evt = _fixture.Create(); - var instance = _fixture.Create(); + [Fact] + public void ShouldAddAThreadNameProperty() + { + var evt = _fixture.Create(); + var instance = new LogglyFormatter(new Config()); - var result = instance.ToJson(evt); - dynamic json = JObject.Parse(result); + var result = instance.ToJson(evt, evt.RenderedMessage); + dynamic json = JObject.Parse(result); - var threadName = (string)json.threadName; + var threadName = (string)json.threadName; - threadName.Should().StartWith("ThreadName", "because this is the value of the ThreadName property on the event"); - } + threadName.Should().StartWith("ThreadName", "because this is the value of the ThreadName property on the event"); + } - [Fact] - public void ShouldAddAValidTimestampProperty() - { - var evt = _fixture.Create(); - var instance = _fixture.Create(); + [Fact] + public void ShouldAddAValidTimestampProperty() + { + var evt = _fixture.Create(); + var instance = new LogglyFormatter(new Config()); - var result = instance.ToJson(evt); - dynamic json = JObject.Parse(result); + var result = instance.ToJson(evt, evt.RenderedMessage); + dynamic json = JObject.Parse(result); - var timestamp = (string)json.timestamp; - DateTime voidDateTime; + var timestamp = (string)json.timestamp; - timestamp.Should().NotBeNullOrEmpty("because the timestamp property should always be set"); - DateTime.TryParse(timestamp, out voidDateTime).Should().BeTrue("because the timestamp should always be a valid date"); - } + timestamp.Should().NotBeNullOrEmpty("because the timestamp property should always be set"); + DateTime.TryParse(timestamp, out _).Should().BeTrue("because the timestamp should always be a valid date"); + } - [Fact] - public void ShouldAddExtraPropertiesWhenMessageObjectIsAComplexType() - { - var evt = new LoggingEvent( - GetType(), - Mock.Of(), - _fixture.Create("loggerName"), - _fixture.Create(), - _fixture.Create(), - null); - var instance = _fixture.Create(); - - var result = instance.ToJson(evt); - dynamic json = JObject.Parse(result); - - var propertyOne = (string)json.PropertyOne; - var propertyTwo = (int)json.PropertyTwo; - - propertyOne.Should().StartWith("PropertyOne", "because the value from the PropertyOne property on the complex type is used"); - propertyTwo.Should().BeGreaterThan(0, "because the value of the PropertyTwo property on the complex type is used"); - } + [Fact] + public void ShouldAddExtraPropertiesWhenMessageObjectIsAComplexType() + { + var evt = new LoggingEvent( + GetType(), + null, + _fixture.Create("loggerName"), + _fixture.Create(), + _fixture.Create(), + null); + var instance = new LogglyFormatter(new Config()); + + var result = instance.ToJson(evt, evt.RenderedMessage); + dynamic json = JObject.Parse(result); + + var propertyOne = (string)json.PropertyOne; + var propertyTwo = (int)json.PropertyTwo; + + propertyOne.Should().StartWith("PropertyOne", "because the value from the PropertyOne property on the complex type is used"); + propertyTwo.Should().BeGreaterThan(0, "because the value of the PropertyTwo property on the complex type is used"); + } - [Fact] - public void ShouldReturnValidJson() - { - var evt = _fixture.Create(); - var instance = _fixture.Create(); + [Fact] + public void ShouldReturnValidJson() + { + var evt = _fixture.Create(); + var instance = new LogglyFormatter(new Config()); - var result = instance.ToJson(evt); - Action act = () => JObject.Parse(result); + var result = instance.ToJson(evt, evt.RenderedMessage); + Action act = () => JObject.Parse(result); - act.ShouldNotThrow("because the result should be a valid json document"); - } + act.Should().NotThrow("because the result should be a valid json document"); + } + + [Fact] + public void ShouldSerializeEventProperties() + { + var evt = _fixture.Create(); + + evt.Properties["Key1"] = _fixture.Create("value1"); + evt.Properties["Key2"] = _fixture.Create(); + evt.Properties["Key3"] = _fixture.Create(); + evt.Properties["Key4"] = _fixture.Create(); + evt.Properties["Key5"] = null; + + var instance = new LogglyFormatter(new Config()); + + var result = instance.ToJson(evt, evt.RenderedMessage); + dynamic json = JObject.Parse(result); + + var key1 = json.Key1; + var key2 = json.Key2; + var key3 = json.Key3; + var key4 = json.Key4; + var key5 = json.Key5; + + ((string)key1).Should().StartWith("value1", "because that's the value of the event property with this key"); + ((int)key2).Should().BeGreaterThan(0, "because the key is set to a positive value in the event properties"); + ((object)key3).Should().NotBeNull("because the key is set in the event properties"); + ((string)key3.PropertyOne).Should().StartWith("PropertyOne", "because the value of the complex type should be serialized"); + ((int)key3.PropertyTwo).Should().BeGreaterThan(0, "because the value of the complex type should be serialized"); + ((object)key4).Should().NotBeNull("because the key is set in the event properties"); + ((string)key4).Should().Be("I'm a fixed type!", "because the type of this property requires fixing"); + ((object)key5).Should().BeNull("because the key is set but the value is null"); + } + + [Fact] + public void ShouldSerializeGlobalThreadContextProperties() + { + var evt = _fixture.Create(); + + PopulateSixContextProperties(GlobalContext.Properties); - [Fact] - public void ShouldSerializeEventProperties() + var instance = new LogglyFormatter(new Config { - var evt = _fixture.Create(); - - evt.Properties["Key1"] = _fixture.Create("value1"); - evt.Properties["Key2"] = _fixture.Create(); - evt.Properties["Key3"] = _fixture.Create(); - evt.Properties["Key4"] = _fixture.Create(); - evt.Properties["Key5"] = null; - - var instance = _fixture.Create(); - - var result = instance.ToJson(evt); - dynamic json = JObject.Parse(result); - - var key1 = json.Key1; - var key2 = json.Key2; - var key3 = json.Key3; - var key4 = json.Key4; - var key5 = json.Key5; - - ((string)key1).Should().StartWith("value1", "because that's the value of the event property with this key"); - ((int)key2).Should().BeGreaterThan(0, "because the key is set to a positive value in the event properties"); - ((object)key3).Should().NotBeNull("because the key is set in the event properties"); - ((string)key3.PropertyOne).Should().StartWith("PropertyOne", "because the value of the complex type should be serialized"); - ((int)key3.PropertyTwo).Should().BeGreaterThan(0, "because the value of the complex type should be serialized"); - ((object)key4).Should().NotBeNull("because the key is set in the event properties"); - ((string)key4).Should().Be("I'm a fixed type!", "because the type of this property requires fixing"); - ((object)key5).Should().BeNull("because the key is set but the value is null"); - } + GlobalContextKeys = "Key1,Key2,Key3,Key4,Key5" + }); + + var result = instance.ToJson(evt, evt.RenderedMessage); + dynamic json = JObject.Parse(result); + + VerifyContextPropertiesInJson(json); + } + + [Fact] + public void ShouldSerializeLogicalThreadContextProperties() + { + var evt = _fixture.Create(); + + PopulateSixContextProperties(LogicalThreadContext.Properties); - [Fact] - public void ShouldSerializeGlobalThreadContextProperties() + var instance = new LogglyFormatter(new Config { - var evt = _fixture.Create(); - - GlobalContext.Properties["Key1"] = _fixture.Create("value1"); - GlobalContext.Properties["Key2"] = _fixture.Create(); - GlobalContext.Properties["Key3"] = _fixture.Create(); - GlobalContext.Properties["Key4"] = _fixture.Create(); - GlobalContext.Properties["Key5"] = null; - GlobalContext.Properties["Key6"] = _fixture.Create("value1"); - - var instance = _fixture.Create(); - _fixture.Freeze>().SetupGet(x => x.GlobalContextKeys).Returns("Key1,Key2,Key3,Key4,Key5"); - - var result = instance.ToJson(evt); - dynamic json = JObject.Parse(result); - - var key1 = json.Key1; - var key2 = json.Key2; - var key3 = json.Key3; - var key4 = json.Key4; - var key5 = json.Key5; - - ((string)key1).Should().StartWith("value1", "because that's the value of the event property with this key"); - ((int)key2).Should().BeGreaterThan(0, "because the key is set to a positive value in the event properties"); - ((object)key3).Should().NotBeNull("because the key is set in the event properties"); - ((string)key3.PropertyOne).Should().StartWith("PropertyOne", "because the value of the complex type should be serialized"); - ((int)key3.PropertyTwo).Should().BeGreaterThan(0, "because the value of the complex type should be serialized"); - ((object)key4).Should().NotBeNull("because the key is set in the event properties"); - ((string)key4).Should().Be("I'm a fixed type!", "because the type of this property requires fixing"); - ((object)key5).Should().BeNull("because the key is set but the value is null"); - ((object)json.Key6).Should().BeNull("because this key was not marked for serialization"); - } + LogicalThreadContextKeys = "Key1,Key2,Key3,Key4,Key5" + }); + + var result = instance.ToJson(evt, evt.RenderedMessage); + dynamic json = JObject.Parse(result); - [Fact] - public void ShouldSerializeLogicalThreadContextProperties() + VerifyContextPropertiesInJson(json); + } + + [Fact] + public void ShouldSerializeTheException() + { + // In order to populate the stacktrace. + Exception ex; + try { - var evt = _fixture.Create(); - - LogicalThreadContext.Properties["Key1"] = _fixture.Create("value1"); - LogicalThreadContext.Properties["Key2"] = _fixture.Create(); - LogicalThreadContext.Properties["Key3"] = _fixture.Create(); - LogicalThreadContext.Properties["Key4"] = _fixture.Create(); - LogicalThreadContext.Properties["Key5"] = null; - LogicalThreadContext.Properties["Key6"] = _fixture.Create("value1"); - - var instance = _fixture.Create(); - _fixture.Freeze>().SetupGet(x => x.LogicalThreadContextKeys).Returns("Key1,Key2,Key3,Key4,Key5"); - - var result = instance.ToJson(evt); - dynamic json = JObject.Parse(result); - - var key1 = json.Key1; - var key2 = json.Key2; - var key3 = json.Key3; - var key4 = json.Key4; - var key5 = json.Key5; - - ((string)key1).Should().StartWith("value1", "because that's the value of the event property with this key"); - ((int)key2).Should().BeGreaterThan(0, "because the key is set to a positive value in the event properties"); - ((object)key3).Should().NotBeNull("because the key is set in the event properties"); - ((string)key3.PropertyOne).Should().StartWith("PropertyOne", "because the value of the complex type should be serialized"); - ((int)key3.PropertyTwo).Should().BeGreaterThan(0, "because the value of the complex type should be serialized"); - ((object)key4).Should().NotBeNull("because the key is set in the event properties"); - ((string)key4).Should().Be("I'm a fixed type!", "because the type of this property requires fixing"); - ((object)key5).Should().BeNull("because the key is set but the value is null"); - ((object)json.Key6).Should().BeNull("because this key was not marked for serialization"); + throw new ArgumentException(); } - - [Fact] - public void ShouldSerializeTheException() + catch (Exception e) { - // In order to populate the stacktrace. - Exception ex; - try - { - throw new ArgumentException(); - } - catch (Exception e) - { - ex = e; - } + ex = e; + } - var evt = new LoggingEvent( - GetType(), - Mock.Of(), - _fixture.Create("loggerName"), - _fixture.Create(), - _fixture.Create("message"), - ex); - var instance = _fixture.Create(); + var evt = new LoggingEvent( + GetType(), + CreateMockRepository(), + _fixture.Create("loggerName"), + _fixture.Create(), + _fixture.Create("message"), + ex); + var instance = new LogglyFormatter(new Config()); - var result = instance.ToJson(evt); - dynamic json = JObject.Parse(result); + var result = instance.ToJson(evt, evt.RenderedMessage); + dynamic json = JObject.Parse(result); - var exception = json.exception; + var exception = json.exception; - ((object)exception).Should().NotBeNull("because an exception was specified in the event"); + ((object)exception).Should().NotBeNull("because an exception was specified in the event"); - var message = (string)exception.exceptionMessage; - var type = (string)exception.exceptionType; - var stacktrace = (string)exception.stacktrace; + var message = (string)exception.exceptionMessage; + var type = (string)exception.exceptionType; + var stacktrace = (string)exception.stacktrace; - message.Should().NotBeNullOrEmpty("because an argument exception has a default message"); - type.Should().Be(typeof(ArgumentException).FullName, "because we logged an argument exception"); - stacktrace.Should().NotBeNull("because the exception has a stacktrace"); - } + message.Should().NotBeNullOrEmpty("because an argument exception has a default message"); + type.Should().Be(typeof(ArgumentException).FullName, "because we logged an argument exception"); + stacktrace.Should().NotBeNull("because the exception has a stacktrace"); + } - [Theory] - [InlineData(0, 0, 1)] - [InlineData(1, 1, 1)] - [InlineData(2, 1, 1)] - [InlineData(2, 2, 2)] - [InlineData(2, 2, 3)] - [InlineData(3, 3, 3)] - [InlineData(5, 5, 5)] - [InlineData(5, 5, 10)] - public void ShouldSerializeInnerExceptions(int configurationNumberOfInnerExceptions, int expectedNumberOfException, int innerExceptionsToCreate) + [Theory] + [InlineData(0, 0, 1)] + [InlineData(1, 1, 1)] + [InlineData(2, 1, 1)] + [InlineData(2, 2, 2)] + [InlineData(2, 2, 3)] + [InlineData(3, 3, 3)] + [InlineData(5, 5, 5)] + [InlineData(5, 5, 10)] + public void ShouldSerializeInnerExceptions(int configurationNumberOfInnerExceptions, int expectedNumberOfInnerExceptions, int innerExceptionsToCreate) + { + Exception ex = GetArgumentException(innerExceptionsToCreate + 1); + + var evt = new LoggingEvent( + GetType(), + CreateMockRepository(), + _fixture.Create("loggerName"), + _fixture.Create(), + _fixture.Create("message"), + ex); + var instance = new LogglyFormatter(new Config { - Exception ex = GetArgumentException(innerExceptionsToCreate + 1); + NumberOfInnerExceptions = configurationNumberOfInnerExceptions + }); - var evt = new LoggingEvent( - GetType(), - Mock.Of(), - _fixture.Create("loggerName"), - _fixture.Create(), - _fixture.Create("message"), - ex); - var instance = _fixture.Create(); - _fixture.Freeze>().SetupGet(x => x.NumberOfInnerExceptions).Returns(configurationNumberOfInnerExceptions); + var result = instance.ToJson(evt, evt.RenderedMessage); + dynamic json = JObject.Parse(result); - var result = instance.ToJson(evt); - dynamic json = JObject.Parse(result); + var exception = json.exception; - var exception = json.exception; + ((object)exception).Should().NotBeNull("because an exception was specified in the event"); - ((object)exception).Should().NotBeNull("because an exception was specified in the event"); - - // Validate first level + var count = 0; + while (exception != null) + { var message = (string)exception.exceptionMessage; var type = (string)exception.exceptionType; var stacktrace = (string)exception.stacktrace; - AssertException(message, type, stacktrace, 0); - - // Validate inner exceptions - var count = 0; - var innerException = exception.innerException; - while (innerException != null) + AssertException(message, type, stacktrace, count); + exception = exception.innerException; + if (exception != null) { count++; - message = (string)innerException.innerExceptionMessage; - type = (string)innerException.innerExceptionType; - stacktrace = (string)innerException.innerStacktrace; - AssertException(message, type, stacktrace, count); - innerException = innerException.innerException; } - - count.Should().Be(expectedNumberOfException, "Expects all stacktraces"); } - [Fact] - public void ShouldSerializeThreadContextProperties() - { - var evt = _fixture.Create(); - - ThreadContext.Properties["Key1"] = _fixture.Create("value1"); - ThreadContext.Properties["Key2"] = _fixture.Create(); - ThreadContext.Properties["Key3"] = _fixture.Create(); - ThreadContext.Properties["Key4"] = _fixture.Create(); - ThreadContext.Properties["Key5"] = null; - - var instance = _fixture.Create(); - - var result = instance.ToJson(evt); - dynamic json = JObject.Parse(result); - - var key1 = json.Key1; - var key2 = json.Key2; - var key3 = json.Key3; - var key4 = json.Key4; - var key5 = json.Key5; - - ((string)key1).Should().StartWith("value1", "because that's the value of the event property with this key"); - ((int)key2).Should().BeGreaterThan(0, "because the key is set to a positive value in the event properties"); - ((object)key3).Should().NotBeNull("because the key is set in the event properties"); - ((string)key3.PropertyOne).Should().StartWith("PropertyOne", "because the value of the complex type should be serialized"); - ((int)key3.PropertyTwo).Should().BeGreaterThan(0, "because the value of the complex type should be serialized"); - ((object)key4).Should().NotBeNull("because the key is set in the event properties"); - ((string)key4).Should().Be("I'm a fixed type!", "because the type of this property requires fixing"); - ((object)key5).Should().BeNull("because the key is set but the value is null"); - } + count.Should().Be(expectedNumberOfInnerExceptions, "Expects all stacktraces"); + } - [Fact] - public void ShouldSetMessagePropertyWhenMessageObjectIsString() - { - var evt = new LoggingEvent( - GetType(), - Mock.Of(), - _fixture.Create("loggerName"), - _fixture.Create(), - _fixture.Create("message"), - null); - var instance = _fixture.Create(); + [Fact] + public void ShouldSerializeThreadContextProperties() + { + var evt = _fixture.Create(); + + ThreadContext.Properties["Key1"] = _fixture.Create("value1"); + ThreadContext.Properties["Key2"] = _fixture.Create(); + ThreadContext.Properties["Key3"] = _fixture.Create(); + ThreadContext.Properties["Key4"] = _fixture.Create(); + ThreadContext.Properties["Key5"] = null; + + var instance = new LogglyFormatter(new Config()); + + var result = instance.ToJson(evt, evt.RenderedMessage); + dynamic json = JObject.Parse(result); + + var key1 = json.Key1; + var key2 = json.Key2; + var key3 = json.Key3; + var key4 = json.Key4; + var key5 = json.Key5; + + ((string)key1).Should().StartWith("value1", "because that's the value of the event property with this key"); + ((int)key2).Should().BeGreaterThan(0, "because the key is set to a positive value in the event properties"); + ((object)key3).Should().NotBeNull("because the key is set in the event properties"); + ((string)key3.PropertyOne).Should().StartWith("PropertyOne", "because the value of the complex type should be serialized"); + ((int)key3.PropertyTwo).Should().BeGreaterThan(0, "because the value of the complex type should be serialized"); + ((object)key4).Should().NotBeNull("because the key is set in the event properties"); + ((string)key4).Should().Be("I'm a fixed type!", "because the type of this property requires fixing"); + ((object)key5).Should().BeNull("because the key is set but the value is null"); + } - var result = instance.ToJson(evt); - dynamic json = JObject.Parse(result); + [Fact] + public void ShouldSetMessagePropertyWhenMessageObjectIsString() + { + var evt = new LoggingEvent( + GetType(), + CreateMockRepository(), + _fixture.Create("loggerName"), + _fixture.Create(), + _fixture.Create("message"), + null); + var instance = new LogglyFormatter(new Config()); - var message = (string)json.message; + var result = instance.ToJson(evt, evt.RenderedMessage); + dynamic json = JObject.Parse(result); - message.Should().StartWith("message", "because the MessageObject property value is used"); - } + var message = (string)json.message; - private static ArgumentException GetArgumentException(int numberOfExceptions) - { - try - { - if (--numberOfExceptions > 0) - { - try - { - GetNestedArgumentException(numberOfExceptions); - } - catch (ArgumentException e) - { - throw new ArgumentException("Exception 0", e); - } - } - else - { - throw new ArgumentException("Exception 0"); - } - } - catch (ArgumentException e) + message.Should().StartWith("message", "because the MessageObject property value is used"); + } + + [Fact] + public void ShouldParseJsonString() + { + var evt = new LoggingEvent( + GetType(), + CreateMockRepository(), + _fixture.Create("loggerName"), + _fixture.Create(), + " { \"property1\": \"value1\" }", + null); + var instance = new LogglyFormatter(new Config()); + + var result = instance.ToJson(evt, evt.RenderedMessage); + var json = JObject.Parse(result); + + json.Should().HaveElement("property1").Which.Should().HaveValue("value1"); + } + + [Fact] + public void ShouldSerializeCustomObjectToOutput() + { + var evt = new LoggingEvent( + GetType(), + CreateMockRepository(), + _fixture.Create("loggerName"), + _fixture.Create(), + new { property1 = "value1" }, + null); + var instance = new LogglyFormatter(new Config()); + + var result = instance.ToJson(evt, evt.RenderedMessage); + var json = JObject.Parse(result); + + json.Should().HaveElement("property1").Which.Should().HaveValue("value1"); + } + + [Fact] + public void ShouldSerializeFormattedString() + { + var evt = new LoggingEvent( + GetType(), + CreateMockRepository(), + _fixture.Create("loggerName"), + _fixture.Create(), + new SystemStringFormat(CultureInfo.InvariantCulture, "test: {0}{1}{2}", 1, 2, 3), + null); + var instance = new LogglyFormatter(new Config()); + + var result = instance.ToJson(evt, evt.RenderedMessage); + var json = JObject.Parse(result); + + json.Should().HaveElement("message").Which.Should().HaveValue("test: 123"); + } + + [Fact] + public void ShouldSerializeRenderedMessageIfNoMessageObjectIsSet() + { + var evt = new LoggingEvent( + GetType(), + CreateMockRepository(), + new LoggingEventData { - return e; - } - return null; - } + Message = "test message" + }); + var instance = new LogglyFormatter(new Config()); + + var result = instance.ToJson(evt, evt.RenderedMessage); + var json = JObject.Parse(result); - private static void GetNestedArgumentException(int numberOfExceptions, int deep = 0) + json.Should().HaveElement("message").Which.Should().HaveValue("test message"); + } + + [Fact] + public void MessageOverTheLimitIsCut() + { + var config = new Config + { + // there is over 150 bytes of fixed JSON unrelated to "message" value (hostname, timestamp, logger name, ...) + // so this value should leave part of the message and cut the rest. + MaxEventSizeBytes = 200 + }; + var formatter = new LogglyFormatter(config); + var evt = new LoggingEvent( + GetType(), + CreateMockRepository(), + "logger", + Level.Info, + null, + null); + + var originalMessage = + "This is very long test log message that will be cut down. This message will be shorter in result " + + "event because it will be cut to fit into max event limit. Actual result size can vary based on values " + + "such as hostname, thread name, process name. It's therefore not possible to check against fixed value, " + + "the test just needs to check that result message is shorter than this one and that the whole event size " + + "fits into max allowed size"; + + var result = formatter.ToJson(evt, originalMessage); + + result.Length.Should().Be(config.MaxEventSizeBytes, "result event size should be within the limit"); + + dynamic json = JObject.Parse(result); + + var message = (string)json.message; + message.Length.Should().BeLessThan(originalMessage.Length, "result message should be shorter than original message"); + originalMessage.Should().StartWith(message, "result message should be beginning of the original message"); + } + + [Fact] + public void EventWithoutMessageExceedingMaxSizeIsDropped() + { + var config = new Config + { + // there is 155 bytes of fixed JSON (for "evt" values below) unrelated to "message" value + // so this value should cut message to first 20 characters + MaxEventSizeBytes = 175 + }; + var formatter = new LogglyFormatter(config); + var evt = new LoggingEvent( + GetType(), + CreateMockRepository(), + "logger", + Level.Info, + new {Property1 = "value1", Property2 = "value2", Property3 = "value3" }, + null); + + var result = formatter.ToJson(evt, ""); + + result.Should().BeNull(); + } + + private static ArgumentException GetArgumentException(int numberOfExceptions) + { + try { - deep++; if (--numberOfExceptions > 0) { try { - GetNestedArgumentException(numberOfExceptions, deep); + GetNestedArgumentException(numberOfExceptions); } catch (ArgumentException e) { - throw new ArgumentException($"Exception {deep}", e); + throw new ArgumentException("Exception 0", e); } } else { - throw new ArgumentException($"Exception {deep}"); + throw new ArgumentException("Exception 0"); } } + catch (ArgumentException e) + { + return e; + } + return null; + } - private static void AssertException(string message, string type, string stacktrace, int stackLevel) + private static void GetNestedArgumentException(int numberOfExceptions, int deep = 0) + { + deep++; + if (--numberOfExceptions > 0) { - message.Should().Be($"Exception {stackLevel}", "because an argument exception has a default message"); - type.Should().Be(typeof(ArgumentException).FullName, "because we logged an argument exception"); - stacktrace.Should().NotBeNull("because the exception has a stacktrace"); + try + { + GetNestedArgumentException(numberOfExceptions, deep); + } + catch (ArgumentException e) + { + throw new ArgumentException($"Exception {deep}", e); + } + } + else + { + throw new ArgumentException($"Exception {deep}"); } } + + private static void AssertException(string message, string type, string stacktrace, int stackLevel) + { + message.Should().Be($"Exception {stackLevel}", "because an argument exception has a default message"); + type.Should().Be(typeof(ArgumentException).FullName, "because we logged an argument exception"); + stacktrace.Should().NotBeNull("because the exception has a stacktrace"); + } + + private void PopulateSixContextProperties(ContextPropertiesBase context) + { + context["Key1"] = _fixture.Create("value1"); + context["Key2"] = _fixture.Create(); + context["Key3"] = _fixture.Create(); + context["Key4"] = _fixture.Create(); + context["Key5"] = null; + context["Key6"] = _fixture.Create("value1"); + } + + private void VerifyContextPropertiesInJson(dynamic json) + { + var key1 = json.Key1; + var key2 = json.Key2; + var key3 = json.Key3; + var key4 = json.Key4; + var key5 = json.Key5; + + ((string)key1).Should().StartWith("value1", "because that's the value of the event property with this key"); + ((int)key2).Should().BeGreaterThan(0, "because the key is set to a positive value in the event properties"); + ((object)key3).Should().NotBeNull("because the key is set in the event properties"); + ((string)key3.PropertyOne).Should().StartWith("PropertyOne", "because the value of the complex type should be serialized"); + ((int)key3.PropertyTwo).Should().BeGreaterThan(0, "because the value of the complex type should be serialized"); + ((object)key4).Should().NotBeNull("because the key is set in the event properties"); + ((string)key4).Should().Be("I'm a fixed type!", "because the type of this property requires fixing"); + ((object)key5).Should().BeNull("because the key is set but the value is null"); + ((object)json.Key6).Should().BeNull("because this key was not marked for serialization"); + } + + private ILoggerRepository CreateMockRepository() + { + var mock = new Mock(); + mock.SetupGet(x => x.RendererMap).Returns(new RendererMap()); + return mock.Object; + } } } diff --git a/source/log4net-loggly.UnitTests/Properties/AssemblyInfo.cs b/source/log4net-loggly.UnitTests/Properties/AssemblyInfo.cs new file mode 100644 index 0000000..0d8e053 --- /dev/null +++ b/source/log4net-loggly.UnitTests/Properties/AssemblyInfo.cs @@ -0,0 +1,4 @@ +using Xunit; + +// log4net initialization is not thread safe and integration tests use it +[assembly: CollectionBehavior(DisableTestParallelization = true)] \ No newline at end of file diff --git a/source/log4net-loggly.UnitTests/log4net-loggly.UnitTests.csproj b/source/log4net-loggly.UnitTests/log4net-loggly.UnitTests.csproj index 7df22db..a122052 100644 --- a/source/log4net-loggly.UnitTests/log4net-loggly.UnitTests.csproj +++ b/source/log4net-loggly.UnitTests/log4net-loggly.UnitTests.csproj @@ -1,30 +1,49 @@ - + netcoreapp2.0 false + + log4net_loggly.UnitTests - - - - - - - + + + + + + + + + - - + + + all + runtime; build; native; contentfiles; analyzers + + + + System + + + + + + Never + + + diff --git a/source/log4net-loggly.sln b/source/log4net-loggly.sln index fe0e2da..35cc5c9 100644 --- a/source/log4net-loggly.sln +++ b/source/log4net-loggly.sln @@ -3,11 +3,18 @@ Microsoft Visual Studio Solution File, Format Version 12.00 # Visual Studio 15 VisualStudioVersion = 15.0.26730.10 MinimumVisualStudioVersion = 10.0.40219.1 -Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "log4net-loggly", "log4net-loggly\log4net-loggly.csproj", "{23BE5AFC-9598-4ECB-8B09-06B6D841B36D}" +Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "log4net-loggly", "log4net-loggly\log4net-loggly.csproj", "{23BE5AFC-9598-4ECB-8B09-06B6D841B36D}" EndProject -Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "log4net-loggly.UnitTests", "log4net-loggly.UnitTests\log4net-loggly.UnitTests.csproj", "{24227290-2834-4C4F-A1EA-4E5F2B28C080}" +Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "log4net-loggly.UnitTests", "log4net-loggly.UnitTests\log4net-loggly.UnitTests.csproj", "{24227290-2834-4C4F-A1EA-4E5F2B28C080}" EndProject -Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "log4net-loggly-console", "log4net-loggly-console\log4net-loggly-console.csproj", "{D93E92BB-9584-4374-AC06-EEE7C616DC3D}" +Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "log4net-loggly-console", "log4net-loggly-console\log4net-loggly-console.csproj", "{D93E92BB-9584-4374-AC06-EEE7C616DC3D}" +EndProject +Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "log4net-loggly-stress-tool", "log4net-loggly-stress-tool\log4net-loggly-stress-tool.csproj", "{DA0CCD2C-C488-4307-AB8F-84823CA46966}" +EndProject +Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "Solution items", "Solution items", "{9D71DE54-AC87-4E49-AE4B-9298F517E2A6}" + ProjectSection(SolutionItems) = preProject + ..\README.md = ..\README.md + EndProjectSection EndProject Global GlobalSection(SolutionConfigurationPlatforms) = preSolution @@ -27,6 +34,10 @@ Global {D93E92BB-9584-4374-AC06-EEE7C616DC3D}.Debug|Any CPU.Build.0 = Debug|Any CPU {D93E92BB-9584-4374-AC06-EEE7C616DC3D}.Release|Any CPU.ActiveCfg = Release|Any CPU {D93E92BB-9584-4374-AC06-EEE7C616DC3D}.Release|Any CPU.Build.0 = Release|Any CPU + {DA0CCD2C-C488-4307-AB8F-84823CA46966}.Debug|Any CPU.ActiveCfg = Debug|Any CPU + {DA0CCD2C-C488-4307-AB8F-84823CA46966}.Debug|Any CPU.Build.0 = Debug|Any CPU + {DA0CCD2C-C488-4307-AB8F-84823CA46966}.Release|Any CPU.ActiveCfg = Release|Any CPU + {DA0CCD2C-C488-4307-AB8F-84823CA46966}.Release|Any CPU.Build.0 = Release|Any CPU EndGlobalSection GlobalSection(SolutionProperties) = preSolution HideSolutionNode = FALSE diff --git a/source/log4net-loggly.sln.DotSettings b/source/log4net-loggly.sln.DotSettings index 62c4425..1c4ed75 100644 --- a/source/log4net-loggly.sln.DotSettings +++ b/source/log4net-loggly.sln.DotSettings @@ -3,4 +3,5 @@ ..\ReSharperTeamShared.DotSettings True True - 1 \ No newline at end of file + 1 + True \ No newline at end of file diff --git a/source/log4net-loggly/Config.cs b/source/log4net-loggly/Config.cs new file mode 100644 index 0000000..da37fa2 --- /dev/null +++ b/source/log4net-loggly/Config.cs @@ -0,0 +1,94 @@ +using System; + +namespace log4net.loggly +{ + /// + /// Class holding configuration for this library + /// + internal class Config + { + public Config() + { + UserAgent = "loggly-log4net-appender"; + TimeoutInSeconds = 30; + MaxSendRetries = 3; + Tag = "log4net"; + LogicalThreadContextKeys = null; + GlobalContextKeys = null; + BufferSize = 500; + NumberOfInnerExceptions = 4; + SendInterval = TimeSpan.FromSeconds(5); + MaxLogQueueSize = 0; // unlimited + FinalFlushWaitTime = TimeSpan.FromSeconds(3); + + // Limitation of HTTP endpoint is 1MB per event, 5MB per bulk: + // https://www.loggly.com/docs/http-endpoint/ and https://www.loggly.com/docs/http-bulk-endpoint/ + + // max 5MB per bulk (real 5*1024*1024 is still rejected so stay a bit under the limit) + MaxBulkSizeBytes = 5242000; + // Real 1024*1024 is still too much for HTTP endpoint so let's stay on safe side with 1000*1000 + MaxEventSizeBytes = 1000000; + } + + /// + /// Max size of whole event sent to Loggly in bytes + /// + public int MaxEventSizeBytes { get; set; } + /// + /// Max size ot one bulk of events sent to Loggly in bytes + /// + public int MaxBulkSizeBytes { get; set; } + /// + /// URL where the logs are sent + /// + public string RootUrl { get; set; } + /// + /// Customer token used to send the logs + /// + public string CustomerToken { get; set; } + /// + /// User agent string used when sending the logs + /// + public string UserAgent { get; set; } + /// + /// Tag or tags separated by commas + /// + public string Tag { get; set; } + /// + /// Comma separated list of keys to LogicalThreadContext whose values will be added to log. + /// + public string LogicalThreadContextKeys { get; set; } + /// + /// Comma separated list of keys to GlobalContext whose values will be added to log. + /// + public string GlobalContextKeys { get; set; } + /// + /// Size of sending buffer + /// + public int BufferSize { get; set; } + /// + /// Maximal size of queue holding logs before send + /// + public int MaxLogQueueSize { get; set; } + /// + /// How many inner exceptions should be sent to Loggly + /// + public int NumberOfInnerExceptions { get; set; } + /// + /// How often should the events buffer be sent if it's not yet full + /// + public TimeSpan SendInterval { get; set; } + /// + /// How long to wait during final appender flush until all messages are flushed. + /// + public TimeSpan FinalFlushWaitTime { get; set; } + /// + /// Request timeout when sending logs to Loggly + /// + public int TimeoutInSeconds { get; set; } + /// + /// How many times library tries to send logs to Loggly before giving up and trying next batch. + /// + public int MaxSendRetries { get; set; } + } +} \ No newline at end of file diff --git a/source/log4net-loggly/ErrorReporter.cs b/source/log4net-loggly/ErrorReporter.cs new file mode 100644 index 0000000..20ab918 --- /dev/null +++ b/source/log4net-loggly/ErrorReporter.cs @@ -0,0 +1,14 @@ +using System; +using System.Diagnostics; + +namespace log4net.loggly +{ + internal static class ErrorReporter + { + public static void ReportError(string error) + { + Trace.WriteLine(error); + Console.WriteLine(error); + } + } +} diff --git a/source/log4net-loggly/ILogglyAppenderConfig.cs b/source/log4net-loggly/ILogglyAppenderConfig.cs deleted file mode 100644 index ea17176..0000000 --- a/source/log4net-loggly/ILogglyAppenderConfig.cs +++ /dev/null @@ -1,16 +0,0 @@ -namespace log4net.loggly -{ - public interface ILogglyAppenderConfig - { - string RootUrl { get; set; } - string InputKey { get; set; } - string UserAgent { get; set; } - string LogMode { get; set; } - int TimeoutInSeconds { get; set; } - string Tag { get; set; } - string LogicalThreadContextKeys { get; set; } - string GlobalContextKeys { get; set; } - int BufferSize { get; set; } - int NumberOfInnerExceptions { get; set; } - } -} \ No newline at end of file diff --git a/source/log4net-loggly/ILogglyAsyncBuffer.cs b/source/log4net-loggly/ILogglyAsyncBuffer.cs new file mode 100644 index 0000000..39ce7ef --- /dev/null +++ b/source/log4net-loggly/ILogglyAsyncBuffer.cs @@ -0,0 +1,20 @@ +using System; + +namespace log4net.loggly +{ + internal interface ILogglyAsyncBuffer : IDisposable + { + /// + /// Buffer message to be sent to Loggly + /// + void BufferForSend(string message); + + /// + /// Flush any buffered messages right now. + /// This method returns once all messages are flushed or when timeout expires. + /// If new messages are coming during flush they will be included and may delay flush operation. + /// + /// Returns "true" if all messages were flushed, "false" if timeout expired before flushing all. + bool Flush(TimeSpan maxWait); + } +} \ No newline at end of file diff --git a/source/log4net-loggly/ILogglyClient.cs b/source/log4net-loggly/ILogglyClient.cs index 2646adb..78765eb 100644 --- a/source/log4net-loggly/ILogglyClient.cs +++ b/source/log4net-loggly/ILogglyClient.cs @@ -1,8 +1,15 @@ namespace log4net.loggly { - public interface ILogglyClient + internal interface ILogglyClient { - void Send(ILogglyAppenderConfig config, string message); - void Send(ILogglyAppenderConfig config, string message, bool isBulk); + /// + /// Send array of messages to Loggly + /// + /// Buffer containing messages to send. Buffer does not have to be full. + /// Number of valid messages in buffer is passed via parameters. + /// Anything past this number should be ignored. + /// + /// Number of messages from buffer to send. + void Send(string[] messagesBuffer, int numberOfMessages); } } \ No newline at end of file diff --git a/source/log4net-loggly/ILogglyFormatter.cs b/source/log4net-loggly/ILogglyFormatter.cs index 0b4b023..47ea937 100644 --- a/source/log4net-loggly/ILogglyFormatter.cs +++ b/source/log4net-loggly/ILogglyFormatter.cs @@ -1,22 +1,15 @@ -using System.Collections.Generic; using log4net.Core; -using System; namespace log4net.loggly { - public interface ILogglyFormatter + internal interface ILogglyFormatter { - void AppendAdditionalLoggingInformation(ILogglyAppenderConfig unknown, LoggingEvent loggingEvent); - string ToJson(LoggingEvent loggingEvent); - string ToJson(IEnumerable loggingEvents); - /// - /// Merged Layout formatted log with the formatted timestamp + /// Format event as JSON. /// - /// - /// + /// Event to format + /// Event message rendered by log4net. /// - string ToJson(string renderedLog, DateTime timeStamp); - + string ToJson(LoggingEvent loggingEvent, string renderedMessage); } } \ No newline at end of file diff --git a/source/log4net-loggly/LogglyAppender.cs b/source/log4net-loggly/LogglyAppender.cs index 4b189fa..e410ff7 100644 --- a/source/log4net-loggly/LogglyAppender.cs +++ b/source/log4net-loggly/LogglyAppender.cs @@ -1,106 +1,134 @@ -using log4net.Appender; -using log4net.Core; -using System; -using System.Collections.Generic; -using Timer = System.Timers; - - - -namespace log4net.loggly -{ - public class LogglyAppender : AppenderSkeleton - { - List lstLogs = new List(); - string[] arr = new string[100]; - public readonly string InputKeyProperty = "LogglyInputKey"; - public ILogglyFormatter Formatter = new LogglyFormatter(); - public ILogglyClient Client = new LogglyClient(); - public LogglySendBufferedLogs _sendBufferedLogs = new LogglySendBufferedLogs(); - private ILogglyAppenderConfig Config = new LogglyAppenderConfig(); - public string RootUrl { set { Config.RootUrl = value; } } - public string InputKey { set { Config.InputKey = value; } } - public string UserAgent { set { Config.UserAgent = value; } } - public string LogMode { set { Config.LogMode = value; } } - public int TimeoutInSeconds { set { Config.TimeoutInSeconds = value; } } - public string Tag { set { Config.Tag = value; } } - public string LogicalThreadContextKeys { set { Config.LogicalThreadContextKeys = value; } } - public string GlobalContextKeys { set { Config.GlobalContextKeys = value; } } - public int BufferSize { set { Config.BufferSize = value; } } - public int NumberOfInnerExceptions { set { Config.NumberOfInnerExceptions = value; } } - - private LogglyAsyncHandler LogglyAsync; - - public LogglyAppender() - { - LogglyAsync = new LogglyAsyncHandler(); - Timer.Timer t = new Timer.Timer(); - t.Interval = 5000; - t.Enabled = true; - t.Elapsed += t_Elapsed; - } - - void t_Elapsed(object sender, Timer.ElapsedEventArgs e) - { - if (lstLogs.Count != 0) - { - SendAllEvents(lstLogs.ToArray()); - } - _sendBufferedLogs.sendBufferedLogsToLoggly(Config, Config.LogMode == "bulk/"); - } - - protected override void Append(LoggingEvent loggingEvent) - { - SendLogAction(loggingEvent); - } - - private void SendLogAction(LoggingEvent loggingEvent) - { - //we should always format event in the same thread as - //many properties used in the event are associated with the current thread - //like threadname, ndc stacks, threadcontent properties etc. - - //initializing a string for the formatted log - string _formattedLog = string.Empty; - - //if Layout is null then format the log from the Loggly Client - if (this.Layout == null) - { - Formatter.AppendAdditionalLoggingInformation(Config, loggingEvent); - _formattedLog = Formatter.ToJson(loggingEvent); - } - else - { - _formattedLog = Formatter.ToJson(RenderLoggingEvent(loggingEvent), loggingEvent.TimeStamp); - } - - //check if logMode is bulk or inputs - if (Config.LogMode == "bulk/") - { - addToBulk(_formattedLog); - } - else if (Config.LogMode == "inputs/") - { - //sending _formattedLog to the async queue - LogglyAsync.PostMessage(_formattedLog, Config); - } - } - - public void addToBulk(string log) - { - // store all events into a array max lenght is 100 - lstLogs.Add(log.Replace("\n", "")); - if (lstLogs.Count == 100) - { - SendAllEvents(lstLogs.ToArray()); - } - } - - private void SendAllEvents(string[] events) - { - lstLogs.Clear(); - String bulkLog = String.Join(System.Environment.NewLine, events); - LogglyAsync.PostMessage(bulkLog, Config); - } - - } +using log4net.Appender; +using log4net.Core; +using System; + +namespace log4net.loggly +{ + public class LogglyAppender : AppenderSkeleton + { + private ILogglyFormatter _formatter; + private ILogglyAsyncBuffer _buffer; + private readonly Config _config; + private ILogglyClient _client; + + public LogglyAppender() + { + _config = new Config(); + } + + internal LogglyAppender(Config config, ILogglyFormatter formatter, ILogglyAsyncBuffer buffer) + : this() + { + _config = config; + _formatter = formatter; + _buffer = buffer; + } + + public override void ActivateOptions() + { + base.ActivateOptions(); + _formatter = _formatter ?? new LogglyFormatter(_config); + _client = new LogglyClient(_config); + _buffer = _buffer ?? new LogglyAsyncBuffer(_config, _client); + } + + protected override void Append(LoggingEvent loggingEvent) + { + // We should always format event in the same thread as + // many properties used in the event are associated with the current thread. + + // if user defined layout let it render the message based on layout, otherwise get message from event + var renderedMessage = Layout != null + ? RenderLoggingEvent(loggingEvent) + : loggingEvent.RenderedMessage; + + var formattedLog = _formatter.ToJson(loggingEvent, renderedMessage); + if (formattedLog != null) + { + _buffer.BufferForSend(formattedLog); + } + } + + public override bool Flush(int millisecondsTimeout) + { + return _buffer.Flush(TimeSpan.FromMilliseconds(millisecondsTimeout)); + } + + protected override void OnClose() + { + base.OnClose(); + _buffer.Flush(_config.FinalFlushWaitTime); + _buffer.Dispose(); + _buffer = null; + } + + #region Configuration properties + public string RootUrl + { + get => _config.RootUrl; + set => _config.RootUrl = value; + } + + [Obsolete("This is old config key for customer token. It's now suggested to use more readable 'customerToken'")] + public string InputKey + { + get => CustomerToken; + set => CustomerToken = value; + } + + public string CustomerToken + { + get => _config.CustomerToken; + set => _config.CustomerToken = value; + } + + public string UserAgent + { + get => _config.UserAgent; + set => _config.UserAgent = value; + } + + public int TimeoutInSeconds + { + get => _config.TimeoutInSeconds; + set => _config.TimeoutInSeconds = value; + } + + public string Tag + { + get => _config.Tag; + set => _config.Tag = value; + } + + public string LogicalThreadContextKeys + { + get => _config.LogicalThreadContextKeys; + set => _config.LogicalThreadContextKeys = value; + } + + public string GlobalContextKeys + { + get => _config.GlobalContextKeys; + set => _config.GlobalContextKeys = value; + } + + public int BufferSize + { + get => _config.BufferSize; + set => _config.BufferSize = value; + } + + public TimeSpan SendInterval + { + get => _config.SendInterval; + set => _config.SendInterval = value; + } + + public int NumberOfInnerExceptions + { + get => _config.NumberOfInnerExceptions; + set => _config.NumberOfInnerExceptions = value; + } + #endregion + } } \ No newline at end of file diff --git a/source/log4net-loggly/LogglyAppenderConfig.cs b/source/log4net-loggly/LogglyAppenderConfig.cs deleted file mode 100644 index 5f1c4f4..0000000 --- a/source/log4net-loggly/LogglyAppenderConfig.cs +++ /dev/null @@ -1,62 +0,0 @@ -namespace log4net.loggly -{ - public class LogglyAppenderConfig : ILogglyAppenderConfig - { - private string _rootUrl; - private string _logMode; - public string RootUrl - { - get { return _rootUrl; } - set - { - //TODO: validate http and uri - _rootUrl = value; - if (!_rootUrl.EndsWith("/")) - { - _rootUrl += "/"; - } - } - } - - public string LogMode - { - get { return _logMode; } - set - { - _logMode = value; - if (!_logMode.EndsWith("/")) - { - _logMode = _logMode.ToLower() + "/"; - } - } - } - - public string InputKey { get; set; } - - public string UserAgent { get; set; } - - public int TimeoutInSeconds { get; set; } - - public string Tag { get; set; } - - public string LogicalThreadContextKeys { get; set; } - - public string GlobalContextKeys { get; set; } - - public int BufferSize { get; set; } - - public int NumberOfInnerExceptions { get; set; } - - public LogglyAppenderConfig() - { - UserAgent = "loggly-log4net-appender"; - TimeoutInSeconds = 30; - Tag = "log4net"; - LogMode = "bulk"; - LogicalThreadContextKeys = null; - GlobalContextKeys = null; - BufferSize = 500; - NumberOfInnerExceptions = 1; - } - } -} \ No newline at end of file diff --git a/source/log4net-loggly/LogglyAsyncBuffer.cs b/source/log4net-loggly/LogglyAsyncBuffer.cs new file mode 100644 index 0000000..3f66ba5 --- /dev/null +++ b/source/log4net-loggly/LogglyAsyncBuffer.cs @@ -0,0 +1,117 @@ +using System; +using System.Collections.Concurrent; +using System.Diagnostics; +using System.Threading; + +namespace log4net.loggly +{ + internal class LogglyAsyncBuffer : ILogglyAsyncBuffer + { + private readonly Config _config; + private readonly ConcurrentQueue _messages = new ConcurrentQueue(); + private readonly ManualResetEvent _stopEvent = new ManualResetEvent(false); + private readonly ManualResetEvent _readyToSendEvent = new ManualResetEvent(false); + private readonly ManualResetEvent _flushingEvent = new ManualResetEvent(false); + private volatile bool _sendInProgress; + private readonly ILogglyClient _client; + + public LogglyAsyncBuffer(Config config, ILogglyClient client) + { + _config = config; + _client = client; + var sendingThread = new Thread(DoSend) + { + Name = "LogglySendThread", + IsBackground = true + }; + sendingThread.Start(); + } + + /// + /// Buffer message to be sent to Loggly + /// + public void BufferForSend(string message) + { + _messages.Enqueue(message); + + // initiate send if sending one by one or if there is already enough messages for batch + if (_messages.Count >= _config.BufferSize) + { + _readyToSendEvent.Set(); + } + + // keep the queue size under limit if any limit is set + if (_config.MaxLogQueueSize > 0) + { + while (_messages.Count > _config.MaxLogQueueSize) + { + _messages.TryDequeue(out _); + } + } + } + + /// + /// Flush any buffered messages right now. + /// This method returns once all messages are flushed or when timeout expires. + /// If new messages are coming during flush they will be included and may delay flush operation. + /// + public bool Flush(TimeSpan maxWait) + { + Stopwatch flushWatch = Stopwatch.StartNew(); + SpinWait spinWait = new SpinWait(); + int messagesCount; + while (((messagesCount = _messages.Count) > 0 || _sendInProgress) && flushWatch.Elapsed < maxWait) + { + _flushingEvent.Set(); + spinWait.SpinOnce(); + } + + return messagesCount == 0 && !_sendInProgress; + } + + private void DoSend() + { + var sendBuffer = new string[_config.BufferSize]; + + // WaitAny returns index of completed task or WaitTimeout value (number) in case of timeout. + // We want to continue unless _stopEvent was set, so unless returned value is 0 - index of _stopEvent + int flushingHandleIndex = 2; + var handles = new WaitHandle[] { _stopEvent, _readyToSendEvent, _flushingEvent }; + + int triggeredBy; + while ((triggeredBy = WaitHandle.WaitAny(handles, _config.SendInterval)) != 0) + { + // allow sending partial buffer only when it was triggered by timeout or flush + if (triggeredBy != WaitHandle.WaitTimeout && triggeredBy != flushingHandleIndex && _messages.Count < sendBuffer.Length) + { + _readyToSendEvent.Reset(); + continue; + } + + _sendInProgress = true; + int sendBufferIndex = 0; + int bulkSize = 0; + while (sendBufferIndex < sendBuffer.Length + && _messages.TryPeek(out var message) + && bulkSize + message.Length <= _config.MaxBulkSizeBytes) + { + bulkSize += message.Length; + // peek/dequeue happens only in one thread so what we peeked above is what we dequeue here + _messages.TryDequeue(out _); + sendBuffer[sendBufferIndex++] = message; + } + + if (sendBufferIndex > 0) + { + _client.Send(sendBuffer, sendBufferIndex); + } + _sendInProgress = false; + } + } + + public void Dispose() + { + _stopEvent.Set(); + } + } +} \ No newline at end of file diff --git a/source/log4net-loggly/LogglyAsyncHandler.cs b/source/log4net-loggly/LogglyAsyncHandler.cs deleted file mode 100644 index a2559ae..0000000 --- a/source/log4net-loggly/LogglyAsyncHandler.cs +++ /dev/null @@ -1,57 +0,0 @@ -using System.Collections.Concurrent; -using System.Threading; - -namespace log4net.loggly -{ - class LogglyAsyncHandler - { - // Size of the internal event queue. - //protected const int QueueSize = 32768; - protected ILogglyAppenderConfig _config; - - protected bool IsRunning = false; - //static list of all the queues the le appender might be managing. - private ConcurrentBag> _allQueues = new ConcurrentBag>(); - - public ILogglyClient Client = new LogglyClient(); - public LogglyAsyncHandler() - { - Queue = new BlockingCollection(); - _allQueues.Add(Queue); - WorkerThread = new Thread(new ThreadStart(SendLogs)); - WorkerThread.Name = "Loggly Log Appender"; - WorkerThread.IsBackground = true; - } - - protected readonly BlockingCollection Queue; - protected Thread WorkerThread; - - protected virtual void SendLogs() - { - if (this._config != null) - { - while (true) - { - var msg = Queue.Take(); - Client.Send(this._config, msg); - } - } - } - - public void PostMessage(string msg, ILogglyAppenderConfig config) - { - this._config = config; - if (!IsRunning) - { - WorkerThread.Start(); - IsRunning = true; - } - if (!Queue.TryAdd(msg)) - { - Queue.Take(); - Queue.TryAdd(msg); - } - } - } - -} \ No newline at end of file diff --git a/source/log4net-loggly/LogglyBufferringAppender.cs b/source/log4net-loggly/LogglyBufferringAppender.cs deleted file mode 100644 index 338fd4e..0000000 --- a/source/log4net-loggly/LogglyBufferringAppender.cs +++ /dev/null @@ -1,34 +0,0 @@ -using log4net.Appender; -using log4net.Core; - -namespace log4net.loggly -{ - public class LogglyBufferringAppender : BufferingAppenderSkeleton - { - public readonly string InputKeyProperty = "LogglyInputKey"; - - public ILogglyFormatter Formatter = new LogglyFormatter(); - public ILogglyClient Client = new LogglyClient(); - - private ILogglyAppenderConfig Config = new LogglyAppenderConfig(); - - public string RootUrl { set { Config.RootUrl = value; } } - public string InputKey { set { Config.InputKey = value; } } - public string UserAgent { set { Config.UserAgent = value; } } - public string LogMode { set { Config.LogMode = value; } } - public int TimeoutInSeconds { set { Config.TimeoutInSeconds = value; } } - public string Tag { set { Config.Tag = value; } } - public int BufferSize { set { Config.BufferSize = value; } } - - protected override void Append(LoggingEvent loggingEvent) - { - Formatter.AppendAdditionalLoggingInformation(Config, loggingEvent); - base.Append(loggingEvent); - } - - protected override void SendBuffer(LoggingEvent[] loggingEvents) - { - Client.Send(Config, Formatter.ToJson(loggingEvents)); - } - } -} \ No newline at end of file diff --git a/source/log4net-loggly/LogglyClient.cs b/source/log4net-loggly/LogglyClient.cs index 112ba13..cb6ef63 100644 --- a/source/log4net-loggly/LogglyClient.cs +++ b/source/log4net-loggly/LogglyClient.cs @@ -1,145 +1,99 @@ using System; -using System.Collections.Generic; using System.Net; using System.Text; -using System.Linq; namespace log4net.loggly { - public class LogglyClient : ILogglyClient + internal class LogglyClient : ILogglyClient { - bool isValidToken = true; - public LogglyStoreLogsInBuffer _storeLogsInBuffer = new LogglyStoreLogsInBuffer(); + private readonly Config _config; + private bool _isTokenValid = true; + private readonly string _url; + private const string BulkPath = "bulk/"; - public void setTokenValid(bool flag) - { - isValidToken = flag; - } + // exposing way how web request is created to allow integration testing + internal static Func WebRequestFactory = CreateWebRequest; - public void storeLogs(string message, ILogglyAppenderConfig config, bool isBulk) + public LogglyClient(Config config) { - List messageBulk = new List(); - if (isBulk) - { - messageBulk = message.Split('\n').ToList(); - _storeLogsInBuffer.storeBulkLogs(config, messageBulk, isBulk); - } - else - { - _storeLogsInBuffer.storeInputLogs(config, message, isBulk); - } + _config = config; + _url = BuildUrl(config); } - void printErrorMessage(string message) + public void Send(string[] messagesBuffer, int numberOfMessages) { - Console.WriteLine("Loggly error: {0}", message); - } - - public virtual void Send(ILogglyAppenderConfig config, string message) - { - int maxRetryAllowed = 5; - int totalRetries = 0; - - string _tag = config.Tag; - bool isBulk = config.LogMode.Contains("bulk"); - - HttpWebResponse webResponse; - HttpWebRequest webRequest; - - //keeping userAgent backward compatible - if (!string.IsNullOrWhiteSpace(config.UserAgent)) - { - _tag = _tag + "," + config.UserAgent; - } - - while (isValidToken && totalRetries < maxRetryAllowed) + string message = string.Join(Environment.NewLine, messagesBuffer, 0, numberOfMessages); + int currentRetry = 0; + // setting MaxSendRetries means that we retry forever, we never throw away logs without delivering them + while (_isTokenValid && (_config.MaxSendRetries < 0 || currentRetry <= _config.MaxSendRetries)) { - totalRetries++; try { - var bytes = Encoding.UTF8.GetBytes(message); - webRequest = CreateWebRequest(config, _tag); - - using (var dataStream = webRequest.GetRequestStream()) - { - dataStream.Write(bytes, 0, bytes.Length); - dataStream.Flush(); - dataStream.Close(); - } - webResponse = (HttpWebResponse)webRequest.GetResponse(); - webResponse.Close(); + SendToLoggly(message); break; } - catch (WebException e) { - if (totalRetries == 1) + var response = (HttpWebResponse)e.Response; + if (response != null && response.StatusCode == HttpStatusCode.Forbidden) { - var response = (HttpWebResponse)e.Response; - if (response != null) - { - // Check for bad token - if (response.StatusCode == HttpStatusCode.Forbidden) - { - // set valid token flag to false - setTokenValid(false); - } - else - { - // store logs to buffer - storeLogs(message, config, isBulk); - } - printErrorMessage(e.Message); - } - else - { - // store logs to buffer - storeLogs(message, config, isBulk); - } + _isTokenValid = false; + ErrorReporter.ReportError($"LogglyClient: Provided Loggly customer token '{_config.CustomerToken}' is invalid. No logs will be sent to Loggly."); + } + else + { + ErrorReporter.ReportError($"LogglyClient: Error sending logs to Loggly: {e.Message}"); } - } - finally - { - webRequest = null; - webResponse = null; - GC.Collect(); + currentRetry++; + if (currentRetry > _config.MaxSendRetries) + { + ErrorReporter.ReportError($"LogglyClient: Maximal number of retries ({_config.MaxSendRetries}) reached. Discarding current batch of logs and moving on to the next one."); + } } } } - public void Send(ILogglyAppenderConfig config, string message, bool isbulk) + private static string BuildUrl(Config config) { - if (isValidToken) + string tag = config.Tag; + + // keeping userAgent backward compatible + if (!string.IsNullOrWhiteSpace(config.UserAgent)) { - string _tag = config.Tag; + tag = tag + "," + config.UserAgent; + } - //keeping userAgent backward compatible - if (!string.IsNullOrWhiteSpace(config.UserAgent)) - { - _tag = _tag + "," + config.UserAgent; - } - var bytes = Encoding.UTF8.GetBytes(message); - var webRequest = CreateWebRequest(config, _tag); + StringBuilder sb = new StringBuilder(config.RootUrl); + if (sb.Length > 0 && sb[sb.Length - 1] != '/') + { + sb.Append("/"); + } - using (var dataStream = webRequest.GetRequestStream()) - { - dataStream.Write(bytes, 0, bytes.Length); - dataStream.Flush(); - dataStream.Close(); - } - var webResponse = (HttpWebResponse)webRequest.GetResponse(); - webResponse.Close(); + sb.Append(BulkPath); + sb.Append(config.CustomerToken); + sb.Append("/tag/"); + sb.Append(tag); + return sb.ToString(); + } + + private void SendToLoggly(string message) + { + var webRequest = WebRequestFactory(_config, _url); + using (var dataStream = webRequest.GetRequestStream()) + { + var bytes = Encoding.UTF8.GetBytes(message); + dataStream.Write(bytes, 0, bytes.Length); + dataStream.Flush(); + dataStream.Close(); } + var webResponse = webRequest.GetResponse(); + webResponse.Close(); } - protected virtual HttpWebRequest CreateWebRequest(ILogglyAppenderConfig config, string tag) + internal static WebRequest CreateWebRequest(Config config, string url) { - var url = String.Concat(config.RootUrl, config.LogMode, config.InputKey); - //adding userAgent as tag in the log - url = String.Concat(url, "/tag/" + tag); - HttpWebRequest request = null; - request = (HttpWebRequest)WebRequest.Create(url); + var request = (HttpWebRequest)WebRequest.Create(url); request.Method = "POST"; request.ReadWriteTimeout = request.Timeout = config.TimeoutInSeconds * 1000; request.UserAgent = config.UserAgent; diff --git a/source/log4net-loggly/LogglyFormatter.cs b/source/log4net-loggly/LogglyFormatter.cs index b451dc2..3ad3c6e 100644 --- a/source/log4net-loggly/LogglyFormatter.cs +++ b/source/log4net-loggly/LogglyFormatter.cs @@ -1,334 +1,278 @@ -namespace log4net.loggly -{ - using System; - using System.Collections; - using System.Collections.Generic; - using System.Diagnostics; - using System.Dynamic; - using System.Linq; - using System.Text; - using Core; - using Newtonsoft.Json; - using Newtonsoft.Json.Linq; - - public class LogglyFormatter : ILogglyFormatter - { - private readonly Process _currentProcess; - - public int EVENT_SIZE = 1000 * 1000; - - public LogglyFormatter() - { - _currentProcess = Process.GetCurrentProcess(); - } - - public ILogglyAppenderConfig Config { get; set; } - - public virtual void AppendAdditionalLoggingInformation(ILogglyAppenderConfig config, LoggingEvent loggingEvent) - { - Config = config; - } - - public virtual string ToJson(LoggingEvent loggingEvent) - { - return PreParse(loggingEvent); - } - - public virtual string ToJson(IEnumerable loggingEvents) - { - return JsonConvert.SerializeObject( - loggingEvents.Select(PreParse), - new JsonSerializerSettings - { - ReferenceLoopHandling = ReferenceLoopHandling.Ignore - }); - } - - public virtual string ToJson(string renderedLog, DateTime timeStamp) - { - return ParseRenderedLog(renderedLog, timeStamp); - } - - private static bool TryGetPropertyValue(object property, out object propertyValue) - { - var fixedProperty = property as IFixingRequired; - if (fixedProperty != null && fixedProperty.GetFixedObject() != null) - { - propertyValue = fixedProperty.GetFixedObject(); - } - else - { - propertyValue = property; - } - - return propertyValue != null; - } - - /// - /// Returns the exception information. Also takes care of the InnerException. - /// - /// - /// - private object GetExceptionInfo(LoggingEvent loggingEvent) - { - if (loggingEvent.ExceptionObject == null) - { - return null; - } - - dynamic exceptionInfo = new ExpandoObject(); - exceptionInfo.exceptionType = loggingEvent.ExceptionObject.GetType().FullName; - exceptionInfo.exceptionMessage = loggingEvent.ExceptionObject.Message; - exceptionInfo.stacktrace = loggingEvent.ExceptionObject.StackTrace; - exceptionInfo.innerException = - GetInnerExceptions(loggingEvent.ExceptionObject.InnerException, Config.NumberOfInnerExceptions); +using System; +using System.Collections; +using System.Diagnostics; +using System.Linq; +using System.Text; +using log4net.Core; +using Newtonsoft.Json; +using Newtonsoft.Json.Linq; + +namespace log4net.loggly +{ + internal class LogglyFormatter : ILogglyFormatter + { + private readonly Config _config; + private readonly Process _currentProcess; + private readonly JsonSerializer _jsonSerializer = JsonSerializer.CreateDefault(new JsonSerializerSettings + { + PreserveReferencesHandling = PreserveReferencesHandling.Arrays, + ReferenceLoopHandling = ReferenceLoopHandling.Ignore + }); + + public LogglyFormatter(Config config) + { + _config = config; + _currentProcess = Process.GetCurrentProcess(); + } + + public string ToJson(LoggingEvent loggingEvent, string renderedMessage) + { + // formatting base logging info + JObject loggingInfo = new JObject + { + ["timestamp"] = loggingEvent.TimeStamp.ToString(@"yyyy-MM-ddTHH\:mm\:ss.fffzzz"), + ["level"] = loggingEvent.Level?.DisplayName, + ["hostName"] = Environment.MachineName, + ["process"] = _currentProcess.ProcessName, + ["threadName"] = loggingEvent.ThreadName, + ["loggerName"] = loggingEvent.LoggerName + }; + + AddMessageOrObjectProperties(loggingInfo, loggingEvent, renderedMessage); + AddExceptionIfPresent(loggingInfo, loggingEvent); + AddContextProperties(loggingInfo, loggingEvent); + + string resultEvent = ToJsonString(loggingInfo); + + int eventSize = Encoding.UTF8.GetByteCount(resultEvent); + + // Be optimistic regarding max event size, first serialize and then check against the limit. + // Only if the event is bigger than allowed go back and try to trim exceeding data. + if (eventSize > _config.MaxEventSizeBytes) + { + int bytesOver = eventSize - _config.MaxEventSizeBytes; + // ok, we are over, try to look at plain "message" and cut that down if possible + if (loggingInfo["message"] != null) + { + var fullMessage = loggingInfo["message"].Value(); + var originalMessageLength = fullMessage.Length; + var newMessageLength = Math.Max(0, originalMessageLength - bytesOver); + loggingInfo["message"] = fullMessage.Substring(0, newMessageLength); + bytesOver -= originalMessageLength - newMessageLength; + } + + // Message cut and still over? We can't shorten this event further, drop it, + // otherwise it will be rejected down the line anyway and we won't be able to identify it so easily. + if (bytesOver > 0) + { + ErrorReporter.ReportError( + $"LogglyFormatter: Dropping log event exceeding allowed limit of {_config.MaxEventSizeBytes} bytes. " + + $"First 500 bytes of dropped event are: {resultEvent.Substring(0, Math.Min(500, resultEvent.Length))}"); + return null; + } + + resultEvent = ToJsonString(loggingInfo); + } + + return resultEvent; + } + + private static string ToJsonString(JObject loggingInfo) + { + return JsonConvert.SerializeObject( + loggingInfo, + new JsonSerializerSettings + { + ReferenceLoopHandling = ReferenceLoopHandling.Ignore, + }); + } + + private void AddContextProperties(JObject loggingInfo, LoggingEvent loggingEvent) + { + if (_config.GlobalContextKeys != null) + { + var globalContextProperties = _config.GlobalContextKeys.Split(','); + foreach (var key in globalContextProperties) + { + if (TryGetPropertyValue(GlobalContext.Properties[key], out var propertyValue)) + { + loggingInfo[key] = JToken.FromObject(propertyValue); + } + } + } + + var threadContextProperties = ThreadContext.Properties.GetKeys(); + if (threadContextProperties != null && threadContextProperties.Any()) + { + foreach (var key in threadContextProperties) + { + if (TryGetPropertyValue(ThreadContext.Properties[key], out var propertyValue)) + { + loggingInfo[key] = JToken.FromObject(propertyValue); + } + } + } + + if (_config.LogicalThreadContextKeys != null) + { + var logicalThreadContextProperties = _config.LogicalThreadContextKeys.Split(','); + foreach (var key in logicalThreadContextProperties) + { + if (TryGetPropertyValue(LogicalThreadContext.Properties[key], out var propertyValue)) + { + loggingInfo[key] = JToken.FromObject(propertyValue); + } + } + } + + if (loggingEvent.Properties.Count > 0) + { + foreach (DictionaryEntry property in loggingEvent.Properties) + { + if (TryGetPropertyValue(property.Value, out var propertyValue)) + { + loggingInfo[(string)property.Key] = JToken.FromObject(propertyValue); + } + } + } + } + + private void AddExceptionIfPresent(JObject loggingInfo, LoggingEvent loggingEvent) + { + dynamic exceptionInfo = GetExceptionInfo(loggingEvent); + if (exceptionInfo != null) + { + loggingInfo["exception"] = exceptionInfo; + } + } + + private void AddMessageOrObjectProperties(JObject loggingInfo, LoggingEvent loggingEvent, string renderedMessage) + { + if (loggingEvent.MessageObject is string messageString) + { + if (CanBeJson(messageString)) + { + // try parse as JSON, otherwise use rendered message passed to this method + try + { + var json = JObject.Parse(messageString); + loggingInfo.Merge(json, + new JsonMergeSettings + { + MergeArrayHandling = MergeArrayHandling.Union + }); + // we have all we need + return; + } + catch (JsonReaderException) + { + // no JSON, handle it as plain string + } + } + + // plain string, use rendered message + loggingInfo["message"] = GetStringFormLog(renderedMessage); + } + else if (loggingEvent.MessageObject == null + // log4net.Util.SystemStringFormat is object used when someone calls log.*Format(...) + // and in that case renderedMessage is what we want + || loggingEvent.MessageObject is Util.SystemStringFormat + // legacy code, it looks that there are cases when the object is StringFormatFormattedMessage, + // but then it should be already in renderedMessage + || (loggingEvent.MessageObject.GetType().FullName?.Contains("StringFormatFormattedMessage") ?? false)) + { + loggingInfo["message"] = GetStringFormLog(renderedMessage); + } + else + { + // serialize object to JSON and add it's properties to loggingInfo + var json = JObject.FromObject(loggingEvent.MessageObject, _jsonSerializer); + loggingInfo.Merge(json, + new JsonMergeSettings + { + MergeArrayHandling = MergeArrayHandling.Union + }); + } + } + + private static bool TryGetPropertyValue(object property, out object propertyValue) + { + if (property is IFixingRequired fixedProperty && fixedProperty.GetFixedObject() != null) + { + propertyValue = fixedProperty.GetFixedObject(); + } + else + { + propertyValue = property; + } + + return propertyValue != null; + } + + /// + /// Returns the exception information. Also takes care of the InnerException. + /// + /// + /// + private JObject GetExceptionInfo(LoggingEvent loggingEvent) + { + if (loggingEvent.ExceptionObject == null) + { + return null; + } + + return GetExceptionInfo(loggingEvent.ExceptionObject, _config.NumberOfInnerExceptions); + } - return exceptionInfo; - } - /// - /// Return nested exceptions + /// Return exception as JObject /// - /// The inner exception + /// Exception to serialize /// The number of inner exceptions that should be included. - /// - private object GetInnerExceptions(Exception innerException, int deep) - { - if (innerException == null || deep <= 0) return null; - dynamic ex = new - { - innerExceptionType = innerException.GetType().FullName, - innerExceptionMessage = innerException.Message, - innerStacktrace = innerException.StackTrace, - innerException = --deep > 0 ? GetInnerExceptions(innerException.InnerException, deep) : null - }; - return ex; - } - - /// - /// Returns a string type message if it is not a custom object, - /// otherwise returns custom object details - /// - /// - /// - /// - private string GetMessageAndObjectInfo(LoggingEvent loggingEvent, out object objInfo) - { - var message = string.Empty; - objInfo = null; - var bytesLengthAllowedToLoggly = EVENT_SIZE; - - if (!string.IsNullOrEmpty(loggingEvent.RenderedMessage)) - { - message = loggingEvent.RenderedMessage; - var messageSizeInBytes = Encoding.Default.GetByteCount(message); - if (messageSizeInBytes > bytesLengthAllowedToLoggly) - { - message = message.Substring(0, bytesLengthAllowedToLoggly); - } - } - else - { - //adding message as null so that the Loggly user - //can know that a null object is logged. - message = "null"; - } - return message; - } - - /// - /// Merged Rendered log and formatted timestamp in the single Json object - /// - /// - /// - /// - private string ParseRenderedLog(string log, DateTime timeStamp) - { - dynamic loggingInfo = new ExpandoObject(); - loggingInfo.timestamp = timeStamp.ToString(@"yyyy-MM-ddTHH\:mm\:ss.fffzzz"); - - string jsonMessage; - if (TryGetParsedJsonFromLog(loggingInfo, log, out jsonMessage)) - { - return jsonMessage; - } - - loggingInfo.message = log; - return JsonConvert.SerializeObject( - loggingInfo, - new JsonSerializerSettings - { - PreserveReferencesHandling = PreserveReferencesHandling.Arrays, - ReferenceLoopHandling = ReferenceLoopHandling.Ignore, - }); - } - - /// - /// Formats the log event to various JSON fields that are to be shown in Loggly. - /// - /// - /// - private string PreParse(LoggingEvent loggingEvent) - { - //formating base logging info - dynamic loggingInfo = new ExpandoObject(); - loggingInfo.timestamp = loggingEvent.TimeStamp.ToString(@"yyyy-MM-ddTHH\:mm\:ss.fffzzz"); - loggingInfo.level = loggingEvent.Level.DisplayName; - loggingInfo.hostName = Environment.MachineName; - loggingInfo.process = _currentProcess.ProcessName; - loggingInfo.threadName = loggingEvent.ThreadName; - loggingInfo.loggerName = loggingEvent.LoggerName; - - //handling messages - object loggedObject; - var message = GetMessageAndObjectInfo(loggingEvent, out loggedObject); - - if (message != string.Empty) - { - loggingInfo.message = message; - } - - //handling exceptions - dynamic exceptionInfo = GetExceptionInfo(loggingEvent); - if (exceptionInfo != null) - { - loggingInfo.exception = exceptionInfo; - } - - var properties = (IDictionary)loggingInfo; - - //handling loggingevent properties - if (loggingEvent.Properties.Count > 0) - { - foreach (DictionaryEntry property in loggingEvent.Properties) - { - object propertyValue; - if (TryGetPropertyValue(property.Value, out propertyValue)) - { - properties[(string)property.Key] = propertyValue; - } - } - } - - //handling threadcontext properties - var threadContextProperties = ThreadContext.Properties.GetKeys(); - if (threadContextProperties != null && threadContextProperties.Any()) - { - foreach (var key in threadContextProperties) - { - object propertyValue; - if (TryGetPropertyValue(ThreadContext.Properties[key], out propertyValue)) - { - properties[key] = propertyValue; - } - } - } - - //handling logicalthreadcontext properties - if (Config.LogicalThreadContextKeys != null) - { - var logicalThreadContextProperties = Config.LogicalThreadContextKeys.Split(','); - foreach (var key in logicalThreadContextProperties) - { - object propertyValue; - if (TryGetPropertyValue(LogicalThreadContext.Properties[key], out propertyValue)) - { - properties[key] = propertyValue; - } - } - } - - //handling globalcontext properties - if (Config.GlobalContextKeys != null) - { - var globalContextProperties = Config.GlobalContextKeys.Split(','); - foreach (var key in globalContextProperties) - { - object propertyValue; - if (TryGetPropertyValue(GlobalContext.Properties[key], out propertyValue)) - { - properties[key] = propertyValue; - } - } - } - - string jsonMessage; - if (TryGetParsedJsonFromLog(loggingInfo, loggedObject, out jsonMessage)) - { - return jsonMessage; - } - - //converting event info to Json string - return JsonConvert.SerializeObject( - loggingInfo, - new JsonSerializerSettings - { - ReferenceLoopHandling = ReferenceLoopHandling.Ignore, - }); - } - - /// - /// Tries to merge log with the logged object or rendered log - /// and converts to JSON - /// - /// - /// - /// - /// - private bool TryGetParsedJsonFromLog(dynamic loggingInfo, object loggingObject, out string loggingEventJson) - { - //serialize the dynamic object to string - loggingEventJson = JsonConvert.SerializeObject( - loggingInfo, - new JsonSerializerSettings - { - ReferenceLoopHandling = ReferenceLoopHandling.Ignore, - }); - - //if loggingObject is null then we need to go to further step - if (loggingObject == null) - { - return false; - } - - try - { - string loggedObjectJson; - if (loggingObject is string) - { - loggedObjectJson = loggingObject.ToString(); - } - else - { - loggedObjectJson = JsonConvert.SerializeObject( - loggingObject, - new JsonSerializerSettings - { - PreserveReferencesHandling = PreserveReferencesHandling.Arrays, - ReferenceLoopHandling = ReferenceLoopHandling.Ignore, - }); - } - - //try to parse the logging object - var jObject = JObject.Parse(loggedObjectJson); - var jEvent = JObject.Parse(loggingEventJson); - - //merge these two objects into one JSON string - jEvent.Merge( - jObject, - new JsonMergeSettings - { - MergeArrayHandling = MergeArrayHandling.Union - }); - - loggingEventJson = jEvent.ToString(); - - return true; - } - catch - { - return false; - } - } - } -} + private JObject GetExceptionInfo(Exception exception, int deep) + { + if (exception == null || deep < 0) + return null; + + var result = new JObject + { + ["exceptionType"] = exception.GetType().FullName, + ["exceptionMessage"] = exception.Message, + ["stacktrace"] = exception.StackTrace, + ["innerException"] = deep-- > 0 ? GetExceptionInfo(exception.InnerException, deep) : null + }; + if (!result["innerException"].HasValues) + { + result.Remove("innerException"); + } + return result; + } + + private bool CanBeJson(string message) + { + // This loop is about 2x faster than message.TrimStart().StartsWith("{") and about 4x faster than Regex("^\s*\{") + foreach (var t in message) + { + // skip leading whitespaces + if (char.IsWhiteSpace(t)) + { + continue; + } + // if first character after whitespace is { then this can be a JSON, otherwise not + if (t == '{') + { + return true; + } + + return false; + } + + return false; + } + + private string GetStringFormLog(string value) + { + return !string.IsNullOrEmpty(value) ? value : "null"; + } + } +} diff --git a/source/log4net-loggly/LogglySendBufferedLogs.cs b/source/log4net-loggly/LogglySendBufferedLogs.cs deleted file mode 100644 index e87f018..0000000 --- a/source/log4net-loggly/LogglySendBufferedLogs.cs +++ /dev/null @@ -1,55 +0,0 @@ -using System; -using System.Collections.Generic; -using System.Linq; -using System.Net; - -namespace log4net.loggly -{ - public class LogglySendBufferedLogs - { - public string message = null; - public List arrayMessage = new List(); - public ILogglyClient Client = new LogglyClient(); - public LogglyClient _logClient = new LogglyClient(); - - public void sendBufferedLogsToLoggly(ILogglyAppenderConfig config, bool isBulk) - { - if (LogglyStoreLogsInBuffer.arrBufferedMessage.Count > 0) - { - int bulkModeBunch = 100; - int inputModeBunch = 1; - int logInBunch = isBulk ? bulkModeBunch : inputModeBunch; - arrayMessage = LogglyStoreLogsInBuffer.arrBufferedMessage.Take(logInBunch).ToList(); - message = isBulk ? String.Join(System.Environment.NewLine, arrayMessage) : arrayMessage[0]; - try - { - Client.Send(config, message, isBulk); - var tempList = LogglyStoreLogsInBuffer.arrBufferedMessage; - if (LogglyStoreLogsInBuffer.arrBufferedMessage.Count < arrayMessage.Count) - { - LogglyStoreLogsInBuffer.arrBufferedMessage.Clear(); - } - else - { - tempList.RemoveRange(0, arrayMessage.Count); - } - LogglyStoreLogsInBuffer.arrBufferedMessage = tempList; - } - catch (WebException e) - { - var response = (HttpWebResponse)e.Response; - if (response != null && response.StatusCode == HttpStatusCode.Forbidden) - { - _logClient.setTokenValid(false); - Console.WriteLine("Loggly error: {0}", e.Message); - return; - } - } - finally - { - GC.Collect(); - } - } - } - } -} diff --git a/source/log4net-loggly/LogglyStoreLogsInBuffer.cs b/source/log4net-loggly/LogglyStoreLogsInBuffer.cs deleted file mode 100644 index 5b4f9bd..0000000 --- a/source/log4net-loggly/LogglyStoreLogsInBuffer.cs +++ /dev/null @@ -1,28 +0,0 @@ -using System; -using System.Collections.Generic; -using System.Linq; - -namespace log4net.loggly -{ - public class LogglyStoreLogsInBuffer - { - public static List arrBufferedMessage = new List(); - - public void storeBulkLogs(ILogglyAppenderConfig config, List logs, bool isBulk) - { - if (logs.Count == 0) return; - int numberOfLogsToBeRemoved = (arrBufferedMessage.Count + logs.Count) - config.BufferSize; - if (numberOfLogsToBeRemoved > 0) arrBufferedMessage.RemoveRange(0, numberOfLogsToBeRemoved); - - arrBufferedMessage = logs.Concat(arrBufferedMessage).ToList(); - } - - public void storeInputLogs(ILogglyAppenderConfig config, string message, bool isBulk) - { - if (message == String.Empty) return; - int numberOfLogsToBeRemoved = (arrBufferedMessage.Count + 1) - config.BufferSize; - if (numberOfLogsToBeRemoved > 0) arrBufferedMessage.RemoveRange(0, numberOfLogsToBeRemoved); - arrBufferedMessage.Add(message); - } - } -} diff --git a/source/log4net-loggly/Properties/AssemblyInfo.cs b/source/log4net-loggly/Properties/AssemblyInfo.cs new file mode 100644 index 0000000..edab490 --- /dev/null +++ b/source/log4net-loggly/Properties/AssemblyInfo.cs @@ -0,0 +1,5 @@ +using System.Runtime.CompilerServices; + +[assembly: InternalsVisibleTo("log4net-loggly.UnitTests")] +[assembly: InternalsVisibleTo("log4net-loggly-stress-tool")] +[assembly: InternalsVisibleTo("DynamicProxyGenAssembly2")] diff --git a/source/log4net-loggly/log4net-loggly.csproj b/source/log4net-loggly/log4net-loggly.csproj index ee01039..1eca5c1 100644 --- a/source/log4net-loggly/log4net-loggly.csproj +++ b/source/log4net-loggly/log4net-loggly.csproj @@ -1,19 +1,28 @@ - + full netstandard2.0;net40 true - 8.0.1 + 9.0.0-beta1 Loggly Loggly http://opensource.org/licenses/MIT Loggly http://github.com/loggly/log4net-loggly - Custom log4Net Appender to send logs to Loggly - .NET Standard 2.0 support with old .NET frameworks and new .NET Core 2.0 compatibility - Copyright 2017 + Custom log4net Appender to send logs to Loggly + + - Fixed serialization of logged objects. They are now again serialized as full JSON instead of their .NET type name. + - Fixed issue when logicalThreadContextKeys and globalContextKeys were ignored if <layout> definition was used. + - Fixed priority of GlobalContext, ThreadContext, LogicalThreadContext and EventContext properties. It was in reverse order than it should be. Correct priority from highest to lowest is EventContext -> LogicalThreadContext -> ThreadContext -> GlobalContext + - Removed option to use Loggly /inputs HTTP endpoint. All logs are sent via /bulk endpoint. + - Changed inner exception property names. Previously the exception properties were named "exceptionType, exceptionMessage" etc. but inner exception properties were "innerExceptionType, innerExceptionMessage" etc. This was unified and inner exception properties are now also named "exceptionType, exceptionMessage" etc. + - Changed default number of inner exceptions that are sent in log from 1 to 4. + - Changed visibility of private/internal classes to be really internal. Only public class is now LogglyAppender. + + Copyright 2019 Loggly-log4net log4net appender logs + log4net.loggly