diff --git a/.gitignore b/.gitignore index 94420dc..c26911d 100644 --- a/.gitignore +++ b/.gitignore @@ -6,6 +6,7 @@ *.user *.userosscache *.sln.docstates +.localHistory/* # User-specific files (MonoDevelop/Xamarin Studio) *.userprefs diff --git a/sample/sampleDurableLogger/Program.cs b/sample/sampleDurableLogger/Program.cs new file mode 100644 index 0000000..25c6afc --- /dev/null +++ b/sample/sampleDurableLogger/Program.cs @@ -0,0 +1,98 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using System.Threading.Tasks; +using Loggly; +using Loggly.Config; +using Serilog; +using Serilog.Core.Enrichers; +using Serilog.Enrichers; +using Serilog.Sinks.RollingFileAlternate; + +namespace sampleDurableLogger +{ + public class Program + { + public static void Main(string[] args) + { + SetupLogglyConfiguration(); + var logger = CreateLoggerFactory(@"c:\test\").CreateLogger(); + + logger.Information((Exception)null, "test message - app started"); + logger.Warning((Exception)null, "test message with {@data}", new { p1 = "sample", p2=DateTime.Now }); + logger.Warning((Exception)null, "test2 message with {@data}", new { p1 = "sample2", p2 = 10 }); + + Console.WriteLine("disconnect to test offline. Two messages will be sent. Press enter to send and wait a minute or so before reconnecting or use breakpoints to see that send fails."); + Console.ReadLine(); + + logger.Information((Exception)null, "second test message - app started"); + logger.Warning((Exception)null, "second test message with {@data}", new { p1 = "sample2", p2 = DateTime.Now }); + + + Console.WriteLine("Offline messages written. Once you have confirmed that messages have been written locally, reconnect to see messages go out. Press Enter for more messages to be written."); + Console.ReadLine(); + + logger.Information((Exception)null, "third test message - app started"); + logger.Warning((Exception)null, "third test message with {@data}", new { p1 = "sample3", p2 = DateTime.Now }); + + Console.WriteLine("back online messages written. Check loggly and files for data. wait a minute or so before reconnecting. Press Enter to temrinate"); + Console.ReadLine(); + } + + public static LoggerConfiguration CreateLoggerFactory(string logFilePath) + { + return new LoggerConfiguration() + .MinimumLevel.Debug() + //Add enrichers + .Enrich.FromLogContext() + .Enrich.WithProcessId() + .Enrich.WithThreadId() + .Enrich.With(new EnvironmentUserNameEnricher()) + .Enrich.With(new MachineNameEnricher()) + .Enrich.With(new PropertyEnricher("Environment", GetLoggingEnvironment())) + //Add sinks + .WriteTo.Async(s => s.Loggly( + bufferBaseFilename: logFilePath + "buffer") + .MinimumLevel.Information() + ) + .WriteTo.Async(s => s.RollingFileAlternate( + logFilePath, + outputTemplate: + "[{ProcessId}] {Timestamp:yyyy-MM-dd HH:mm:ss.fff K} [{ThreadId}] [{Level}] [{SourceContext}] [{Category}] {Message}{NewLine}{Exception}", + fileSizeLimitBytes: 10 * 1024 * 1024, + retainedFileCountLimit: 100) + .MinimumLevel.Debug() + ); + } + + private static string GetLoggingEnvironment() + { + return "development"; + } + + private static void SetupLogglyConfiguration() + { + ///CHANGE THESE TOO TO YOUR LOGGLY ACCOUNT: DO NOT COMMIT TO Source control!!! + const string appName = "AppNameHere"; + const string customerToken = "yourkeyhere"; + + //Configure Loggly + var config = LogglyConfig.Instance; + config.CustomerToken = customerToken; + config.ApplicationName = appName; + config.Transport = new TransportConfiguration() + { + EndpointHostname = "logs-01.loggly.com", + EndpointPort = 443, + LogTransport = LogTransport.Https + }; + config.ThrowExceptions = true; + + //Define Tags sent to Loggly + config.TagConfig.Tags.AddRange(new ITag[]{ + new ApplicationNameTag {Formatter = "application-{0}"}, + new HostnameTag { Formatter = "host-{0}" } + }); + } + } +} diff --git a/sample/sampleDurableLogger/Properties/AssemblyInfo.cs b/sample/sampleDurableLogger/Properties/AssemblyInfo.cs new file mode 100644 index 0000000..c15a5f1 --- /dev/null +++ b/sample/sampleDurableLogger/Properties/AssemblyInfo.cs @@ -0,0 +1,19 @@ +using System.Reflection; +using System.Runtime.CompilerServices; +using System.Runtime.InteropServices; + +// General Information about an assembly is controlled through the following +// set of attributes. Change these attribute values to modify the information +// associated with an assembly. +[assembly: AssemblyConfiguration("")] +[assembly: AssemblyCompany("Microsoft")] +[assembly: AssemblyProduct("sampleDurableLogger")] +[assembly: AssemblyTrademark("")] + +// Setting ComVisible to false makes the types in this assembly not visible +// to COM components. If you need to access a type in this assembly from +// COM, set the ComVisible attribute to true on that type. +[assembly: ComVisible(false)] + +// The following GUID is for the ID of the typelib if this project is exposed to COM +[assembly: Guid("a47ed1ce-fe7c-444e-9391-10d6b60519c2")] diff --git a/sample/sampleDurableLogger/project.json b/sample/sampleDurableLogger/project.json new file mode 100644 index 0000000..a584f19 --- /dev/null +++ b/sample/sampleDurableLogger/project.json @@ -0,0 +1,31 @@ +{ + "version": "1.0.0-*", + "buildOptions": { + "emitEntryPoint": true + }, + + "dependencies": { + "Microsoft.NETCore.App": { + "type": "platform", + "version": "1.0.0" + }, + "loggly-csharp": "4.6.0.5", + "Newtonsoft.Json": "9.0.1", + "Serilog": "2.3.0", + "Serilog.Sinks.PeriodicBatching": "2.0.0", + "Serilog.Sinks.File": "3.1.1", + "Serilog.Sinks.RollingFile": "3.2.0", + "Serilog.Sinks.RollingFileAlternate": "2.0.6", + "Serilog.Sinks.Async": "1.0.1", + "Serilog.Enrichers.Environment": "2.1.1", + "Serilog.Enrichers.Process": "2.0.0", + "Serilog.Enrichers.Thread": "3.0.0", + "Serilog.Sinks.Loggly": "3.0.3-*" + }, + + "frameworks": { + "netcoreapp1.0": { + "imports": "dnxcore50" + } + } +} diff --git a/sample/sampleDurableLogger/sampleDurableLogger.xproj b/sample/sampleDurableLogger/sampleDurableLogger.xproj new file mode 100644 index 0000000..f719e0b --- /dev/null +++ b/sample/sampleDurableLogger/sampleDurableLogger.xproj @@ -0,0 +1,21 @@ + + + + 14.0 + $(MSBuildExtensionsPath32)\Microsoft\VisualStudio\v$(VisualStudioVersion) + + + + + a47ed1ce-fe7c-444e-9391-10d6b60519c2 + sampleDurableLogger + .\obj + .\bin\ + v4.5.2 + + + + 2.0 + + + diff --git a/serilog-sinks-loggly.sln b/serilog-sinks-loggly.sln index 7dbc70b..43fb6e8 100644 --- a/serilog-sinks-loggly.sln +++ b/serilog-sinks-loggly.sln @@ -20,6 +20,10 @@ Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "test", "test", "{2B558B69-8 EndProject Project("{8BB2217D-0F2D-49D1-97BC-3654ED321F3B}") = "Serilog.Sinks.Loggly.Tests", "test\Serilog.Sinks.Loggly.Tests\Serilog.Sinks.Loggly.Tests.xproj", "{120C431E-479C-48C7-9539-CFA32399769C}" EndProject +Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "sample", "sample", "{FD377716-21BA-45D1-9580-02C2BECA5BAB}" +EndProject +Project("{8BB2217D-0F2D-49D1-97BC-3654ED321F3B}") = "sampleDurableLogger", "sample\sampleDurableLogger\sampleDurableLogger.xproj", "{A47ED1CE-FE7C-444E-9391-10D6B60519C2}" +EndProject Global GlobalSection(SolutionConfigurationPlatforms) = preSolution Debug|Any CPU = Debug|Any CPU @@ -34,6 +38,10 @@ Global {120C431E-479C-48C7-9539-CFA32399769C}.Debug|Any CPU.Build.0 = Debug|Any CPU {120C431E-479C-48C7-9539-CFA32399769C}.Release|Any CPU.ActiveCfg = Release|Any CPU {120C431E-479C-48C7-9539-CFA32399769C}.Release|Any CPU.Build.0 = Release|Any CPU + {A47ED1CE-FE7C-444E-9391-10D6B60519C2}.Debug|Any CPU.ActiveCfg = Debug|Any CPU + {A47ED1CE-FE7C-444E-9391-10D6B60519C2}.Debug|Any CPU.Build.0 = Debug|Any CPU + {A47ED1CE-FE7C-444E-9391-10D6B60519C2}.Release|Any CPU.ActiveCfg = Release|Any CPU + {A47ED1CE-FE7C-444E-9391-10D6B60519C2}.Release|Any CPU.Build.0 = Release|Any CPU EndGlobalSection GlobalSection(SolutionProperties) = preSolution HideSolutionNode = FALSE @@ -41,5 +49,6 @@ Global GlobalSection(NestedProjects) = preSolution {94E6E098-11A0-43CF-B0CF-4BA270CE9DBD} = {037440DE-440B-4129-9F7A-09B42D00397E} {120C431E-479C-48C7-9539-CFA32399769C} = {2B558B69-8F95-4F82-B223-EBF60F6F31EE} + {A47ED1CE-FE7C-444E-9391-10D6B60519C2} = {FD377716-21BA-45D1-9580-02C2BECA5BAB} EndGlobalSection EndGlobal diff --git a/src/Serilog.Sinks.Loggly/LoggerConfigurationLogglyExtensions.cs b/src/Serilog.Sinks.Loggly/LoggerConfigurationLogglyExtensions.cs index fab7ae7..8cec4eb 100644 --- a/src/Serilog.Sinks.Loggly/LoggerConfigurationLogglyExtensions.cs +++ b/src/Serilog.Sinks.Loggly/LoggerConfigurationLogglyExtensions.cs @@ -13,7 +13,10 @@ // limitations under the License. using System; +using System.Net.Http; +using Loggly.Config; using Serilog.Configuration; +using Serilog.Core; using Serilog.Events; using Serilog.Sinks.Loggly; @@ -32,6 +35,20 @@ public static class LoggerConfigurationLogglyExtensions /// Supplies culture-specific formatting information, or null. /// The maximum number of events to post in a single batch. /// The time to wait between checking for event batches. + /// Path for a set of files that will be used to buffer events until they + /// can be successfully transmitted across the network. Individual files will be created using the + /// pattern -{Date}.json. + /// The maximum size, in bytes, to which the buffer + /// log file for a specific date will be allowed to grow. By default no limit will be applied. + /// The maximum size, in bytes, that the JSON representation of + /// an event may take before it is dropped rather than being sent to the Loggly server. Specify null for no limit. + /// The default is 1 MB. + /// If provided, the switch will be updated based on the Seq server's level setting + /// for the corresponding API key. Passing the same key to MinimumLevel.ControlledBy() will make the whole pipeline + /// dynamically controlled. Do not specify with this setting. + /// A soft limit for the number of bytes to use for storing failed requests. + /// The limit is soft in that it can be exceeded by any single error payload, but in that case only that single error + /// payload will be retained. /// Logger configuration, allowing configuration to continue. /// A required parameter is null. public static LoggerConfiguration Loggly( @@ -39,15 +56,44 @@ public static LoggerConfiguration Loggly( LogEventLevel restrictedToMinimumLevel = LevelAlias.Minimum, int batchPostingLimit = LogglySink.DefaultBatchPostingLimit, TimeSpan? period = null, - IFormatProvider formatProvider = null) + IFormatProvider formatProvider = null, + string bufferBaseFilename = null, + long? bufferFileSizeLimitBytes = null, + long? eventBodyLimitBytes = 1024 * 1024, + LoggingLevelSwitch controlLevelSwitch = null, + long? retainedInvalidPayloadsLimitBytes = null) { if (loggerConfiguration == null) throw new ArgumentNullException("loggerConfiguration"); + if (bufferFileSizeLimitBytes.HasValue && bufferFileSizeLimitBytes < 0) + throw new ArgumentOutOfRangeException(nameof(bufferFileSizeLimitBytes), "Negative value provided; file size limit must be non-negative."); var defaultedPeriod = period ?? LogglySink.DefaultPeriod; - return loggerConfiguration.Sink( - new LogglySink(formatProvider, batchPostingLimit, defaultedPeriod), - restrictedToMinimumLevel); + ILogEventSink sink; + + if (bufferBaseFilename == null) + { + sink = new LogglySink(formatProvider, batchPostingLimit, defaultedPeriod); + } + else + { +#if DURABLE + sink = new DurableLogglySink( + bufferBaseFilename, + batchPostingLimit, + defaultedPeriod, + bufferFileSizeLimitBytes, + eventBodyLimitBytes, + controlLevelSwitch, + retainedInvalidPayloadsLimitBytes); +#else + // We keep the API consistent for easier packaging and to support bait-and-switch. + throw new NotSupportedException("Durable log shipping is not supported on this platform."); +#endif + + } + + return loggerConfiguration.Sink(sink, restrictedToMinimumLevel); } } diff --git a/src/Serilog.Sinks.Loggly/Sinks/Loggly/ControlledSwitch.cs b/src/Serilog.Sinks.Loggly/Sinks/Loggly/ControlledSwitch.cs new file mode 100644 index 0000000..2115df3 --- /dev/null +++ b/src/Serilog.Sinks.Loggly/Sinks/Loggly/ControlledSwitch.cs @@ -0,0 +1,72 @@ +// Serilog.Sinks.Seq Copyright 2016 Serilog Contributors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +using Serilog.Core; +using Serilog.Events; + +namespace Serilog.Sinks.Loggly +{ + /// + /// Instances of this type are single-threaded, generally only updated on a background + /// timer thread. An exception is , which may be called + /// concurrently but performs no synchronization. + /// + class ControlledLevelSwitch + { + // If non-null, then background level checks will be performed; set either through the constructor + // or in response to a level specification from the server. Never set to null after being made non-null. + LoggingLevelSwitch _controlledSwitch; + LogEventLevel? _originalLevel; + + public ControlledLevelSwitch(LoggingLevelSwitch controlledSwitch = null) + { + _controlledSwitch = controlledSwitch; + } + + public bool IsActive => _controlledSwitch != null; + + public bool IsIncluded(LogEvent evt) + { + // Concurrent, but not synchronized. + var controlledSwitch = _controlledSwitch; + return controlledSwitch == null || + (int)controlledSwitch.MinimumLevel <= (int)evt.Level; + } + + public void Update(LogEventLevel? minimumAcceptedLevel) + { + if (minimumAcceptedLevel == null) + { + if (_controlledSwitch != null && _originalLevel.HasValue) + _controlledSwitch.MinimumLevel = _originalLevel.Value; + + return; + } + + if (_controlledSwitch == null) + { + // The server is controlling the logging level, but not the overall logger. Hence, if the server + // stops controlling the level, the switch should become transparent. + _originalLevel = LevelAlias.Minimum; + _controlledSwitch = new LoggingLevelSwitch(minimumAcceptedLevel.Value); + return; + } + + if (!_originalLevel.HasValue) + _originalLevel = _controlledSwitch.MinimumLevel; + + _controlledSwitch.MinimumLevel = minimumAcceptedLevel.Value; + } + } +} diff --git a/src/Serilog.Sinks.Loggly/Sinks/Loggly/DurableLogglySink.cs b/src/Serilog.Sinks.Loggly/Sinks/Loggly/DurableLogglySink.cs new file mode 100644 index 0000000..c81108d --- /dev/null +++ b/src/Serilog.Sinks.Loggly/Sinks/Loggly/DurableLogglySink.cs @@ -0,0 +1,77 @@ +// Serilog.Sinks.Seq Copyright 2016 Serilog Contributors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +#if DURABLE + +using System; +using System.Text; +using Serilog.Core; +using Serilog.Events; +using Serilog.Sinks.RollingFile; + +namespace Serilog.Sinks.Loggly +{ + class DurableLogglySink : ILogEventSink, IDisposable + { + readonly HttpLogShipper _shipper; + readonly RollingFileSink _sink; + + public DurableLogglySink( + string bufferBaseFilename, + int batchPostingLimit, + TimeSpan period, + long? bufferFileSizeLimitBytes, + long? eventBodyLimitBytes, + LoggingLevelSwitch levelControlSwitch, + long? retainedInvalidPayloadsLimitBytes) + { + if (bufferBaseFilename == null) throw new ArgumentNullException(nameof(bufferBaseFilename)); + + //handles sending events to Loggly's API through LogglyClient and manages the pending list + _shipper = new HttpLogShipper( + bufferBaseFilename, + batchPostingLimit, + period, + eventBodyLimitBytes, + levelControlSwitch, + retainedInvalidPayloadsLimitBytes); + + //writes events to the file to support connection recovery + _sink = new RollingFileSink( + bufferBaseFilename + "-{Date}.json", + new LogglyFormatter(), //serializes as LogglyEvent + bufferFileSizeLimitBytes, + null, + encoding: Encoding.UTF8); + } + + public void Dispose() + { + _sink.Dispose(); + _shipper.Dispose(); + } + + public void Emit(LogEvent logEvent) + { + // This is a lagging indicator, but the network bandwidth usage benefits + // are worth the ambiguity. + if (_shipper.IsIncluded(logEvent)) + { + _sink.Emit(logEvent); + } + } + } +} + +#endif \ No newline at end of file diff --git a/src/Serilog.Sinks.Loggly/Sinks/Loggly/ExponentialBackoffConnectionSchedule.cs b/src/Serilog.Sinks.Loggly/Sinks/Loggly/ExponentialBackoffConnectionSchedule.cs new file mode 100644 index 0000000..013c43c --- /dev/null +++ b/src/Serilog.Sinks.Loggly/Sinks/Loggly/ExponentialBackoffConnectionSchedule.cs @@ -0,0 +1,76 @@ +// Serilog.Sinks.Seq Copyright 2016 Serilog Contributors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +using System; + +namespace Serilog.Sinks.Loggly +{ + /// + /// Based on the BatchedConnectionStatus class from . + /// + class ExponentialBackoffConnectionSchedule + { + static readonly TimeSpan MinimumBackoffPeriod = TimeSpan.FromSeconds(5); + static readonly TimeSpan MaximumBackoffInterval = TimeSpan.FromMinutes(10); + + readonly TimeSpan _period; + + int _failuresSinceSuccessfulConnection; + + public ExponentialBackoffConnectionSchedule(TimeSpan period) + { + if (period < TimeSpan.Zero) throw new ArgumentOutOfRangeException(nameof(period), "The connection retry period must be a positive timespan"); + + _period = period; + } + + public void MarkSuccess() + { + _failuresSinceSuccessfulConnection = 0; + } + + public void MarkFailure() + { + ++_failuresSinceSuccessfulConnection; + } + + public TimeSpan NextInterval + { + get + { + // Available, and first failure, just try the batch interval + if (_failuresSinceSuccessfulConnection <= 1) return _period; + + // Second failure, start ramping up the interval - first 2x, then 4x, ... + var backoffFactor = Math.Pow(2, (_failuresSinceSuccessfulConnection - 1)); + + // If the period is ridiculously short, give it a boost so we get some + // visible backoff. + var backoffPeriod = Math.Max(_period.Ticks, MinimumBackoffPeriod.Ticks); + + // The "ideal" interval + var backedOff = (long)(backoffPeriod * backoffFactor); + + // Capped to the maximum interval + var cappedBackoff = Math.Min(MaximumBackoffInterval.Ticks, backedOff); + + // Unless that's shorter than the base interval, in which case we'll just apply the period + var actual = Math.Max(_period.Ticks, cappedBackoff); + + return TimeSpan.FromTicks(actual); + } + } + } +} + diff --git a/src/Serilog.Sinks.Loggly/Sinks/Loggly/HttpLogShipper.cs b/src/Serilog.Sinks.Loggly/Sinks/Loggly/HttpLogShipper.cs new file mode 100644 index 0000000..4d0a7f1 --- /dev/null +++ b/src/Serilog.Sinks.Loggly/Sinks/Loggly/HttpLogShipper.cs @@ -0,0 +1,437 @@ +// Serilog.Sinks.Seq Copyright 2016 Serilog Contributors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +#if DURABLE + +using System; +using System.IO; +using System.Linq; +using System.Net; +using System.Net.Http; +using System.Text; +using Serilog.Core; +using Serilog.Debugging; +using Serilog.Events; +using IOFile = System.IO.File; +using System.Threading.Tasks; +using System.Collections.Generic; +using Loggly; +using Loggly.Config; +using Newtonsoft.Json; +using Serilog.Parsing; +#if HRESULTS +using System.Runtime.InteropServices; +#endif + +namespace Serilog.Sinks.Loggly +{ + class HttpLogShipper : IDisposable + { + readonly JsonSerializer _serializer = JsonSerializer.Create(); + static readonly TimeSpan RequiredLevelCheckInterval = TimeSpan.FromMinutes(2); + + readonly int _batchPostingLimit; + readonly long? _eventBodyLimitBytes; + readonly string _bookmarkFilename; + readonly string _logFolder; + readonly string _candidateSearchPath; + readonly ExponentialBackoffConnectionSchedule _connectionSchedule; + readonly long? _retainedInvalidPayloadsLimitBytes; + + readonly object _stateLock = new object(); + readonly PortableTimer _timer; + + ControlledLevelSwitch _controlledSwitch; + DateTime _nextRequiredLevelCheckUtc = DateTime.UtcNow.Add(RequiredLevelCheckInterval); + volatile bool _unloading; + + private readonly LogglyClient _logglyClient; + + public HttpLogShipper( + string bufferBaseFilename, + int batchPostingLimit, + TimeSpan period, + long? eventBodyLimitBytes, + LoggingLevelSwitch levelControlSwitch, + long? retainedInvalidPayloadsLimitBytes) + { + _batchPostingLimit = batchPostingLimit; + _eventBodyLimitBytes = eventBodyLimitBytes; + _controlledSwitch = new ControlledLevelSwitch(levelControlSwitch); + _connectionSchedule = new ExponentialBackoffConnectionSchedule(period); + _retainedInvalidPayloadsLimitBytes = retainedInvalidPayloadsLimitBytes; + + _logglyClient = new LogglyClient(); //we'll use the loggly client instead of HTTP directly + + _bookmarkFilename = Path.GetFullPath(bufferBaseFilename + ".bookmark"); + _logFolder = Path.GetDirectoryName(_bookmarkFilename); + _candidateSearchPath = Path.GetFileName(bufferBaseFilename) + "*.json"; + + _timer = new PortableTimer(c => OnTick()); + SetTimer(); + } + + void CloseAndFlush() + { + lock (_stateLock) + { + if (_unloading) + return; + + _unloading = true; + } + + _timer.Dispose(); + + OnTick().GetAwaiter().GetResult(); + } + + public bool IsIncluded(LogEvent logEvent) + { + return _controlledSwitch.IsIncluded(logEvent); + } + + /// + public void Dispose() + { + CloseAndFlush(); + } + + void SetTimer() + { + // Note, called under _stateLock + _timer.Start(_connectionSchedule.NextInterval); + } + + async Task OnTick() + { + LogEventLevel? minimumAcceptedLevel = LogEventLevel.Debug; + + try + { + int count; + do + { + count = 0; + + // Locking the bookmark ensures that though there may be multiple instances of this + // class running, only one will ship logs at a time. + + using (var bookmark = IOFile.Open(_bookmarkFilename, FileMode.OpenOrCreate, FileAccess.ReadWrite, FileShare.Read)) + { + long nextLineBeginsAtOffset; + string currentFile; + + TryReadBookmark(bookmark, out nextLineBeginsAtOffset, out currentFile); + + var fileSet = GetFileSet(); + + if (currentFile == null || !IOFile.Exists(currentFile)) + { + nextLineBeginsAtOffset = 0; + currentFile = fileSet.FirstOrDefault(); + } + + if (currentFile == null) + continue; + + //grab the list of pending LogglyEvents from the file + var payload = GetListOfEvents(currentFile, ref nextLineBeginsAtOffset, ref count); + + if (count > 0 || _controlledSwitch.IsActive && _nextRequiredLevelCheckUtc < DateTime.UtcNow) + { + lock (_stateLock) + { + _nextRequiredLevelCheckUtc = DateTime.UtcNow.Add(RequiredLevelCheckInterval); + } + + //sen the loggly events through the bulk API + var result = await _logglyClient.Log(payload).ConfigureAwait(false); + if (result.Code == ResponseCode.Success) + { + _connectionSchedule.MarkSuccess(); + WriteBookmark(bookmark, nextLineBeginsAtOffset, currentFile); + } + else if (result.Code == ResponseCode.Error) + { + // The connection attempt was successful - the payload we sent was the problem. + _connectionSchedule.MarkSuccess(); + + await DumpInvalidPayload(result, payload).ConfigureAwait(false); + WriteBookmark(bookmark, nextLineBeginsAtOffset, currentFile); + } + else + { + _connectionSchedule.MarkFailure(); + SelfLog.WriteLine("Received failed HTTP shipping result {0}: {1}", result.Code, result.Message); + break; + } + } + else + { + // For whatever reason, there's nothing waiting to send. This means we should try connecting again at the + // regular interval, so mark the attempt as successful. + _connectionSchedule.MarkSuccess(); + + // Only advance the bookmark if no other process has the + // current file locked, and its length is as we found it. + if (fileSet.Length == 2 && fileSet.First() == currentFile && IsUnlockedAtLength(currentFile, nextLineBeginsAtOffset)) + { + WriteBookmark(bookmark, 0, fileSet[1]); + } + + if (fileSet.Length > 2) + { + // Once there's a third file waiting to ship, we do our + // best to move on, though a lock on the current file + // will delay this. + + IOFile.Delete(fileSet[0]); + } + } + } + } + while (count == _batchPostingLimit); + } + catch (Exception ex) + { + SelfLog.WriteLine("Exception while emitting periodic batch from {0}: {1}", this, ex); + _connectionSchedule.MarkFailure(); + } + finally + { + lock (_stateLock) + { + _controlledSwitch.Update(minimumAcceptedLevel); + + if (!_unloading) + SetTimer(); + } + } + } + + const string InvalidPayloadFilePrefix = "invalid-"; + async Task DumpInvalidPayload(LogResponse result, IEnumerable payload) + { + var invalidPayloadFilename = $"{InvalidPayloadFilePrefix}{result.Code}-{Guid.NewGuid():n}.json"; + var invalidPayloadFile = Path.Combine(_logFolder, invalidPayloadFilename); + SelfLog.WriteLine("HTTP shipping failed with {0}: {1}; dumping payload to {2}", result.Code, result.Message, invalidPayloadFile); + + StringWriter writer = new StringWriter(); + SerializeLogglyEventsToWriter(payload, writer); + + var bytesToWrite = Encoding.UTF8.GetBytes(writer.ToString()); + if (_retainedInvalidPayloadsLimitBytes.HasValue) + { + CleanUpInvalidPayloadFiles(_retainedInvalidPayloadsLimitBytes.Value - bytesToWrite.Length, _logFolder); + } + IOFile.WriteAllBytes(invalidPayloadFile, bytesToWrite); + } + + static void CleanUpInvalidPayloadFiles(long maxNumberOfBytesToRetain, string logFolder) + { + try + { + var candiateFiles = Directory.EnumerateFiles(logFolder, $"{InvalidPayloadFilePrefix}*.json"); + DeleteOldFiles(maxNumberOfBytesToRetain, candiateFiles); + } + catch (Exception ex) + { + SelfLog.WriteLine("Exception thrown while trying to clean up invalid payload files: {0}", ex); + } + } + + static IEnumerable WhereCumulativeSizeGreaterThan(IEnumerable files, long maxCumulativeSize) + { + long cumulative = 0; + foreach (var file in files) + { + cumulative += file.Length; + if (cumulative > maxCumulativeSize) + { + yield return file; + } + } + } + + static void DeleteOldFiles(long maxNumberOfBytesToRetain, IEnumerable files) + { + var orderedFileInfos = from candidateFile in files + let candidateFileInfo = new FileInfo(candidateFile) + orderby candidateFileInfo.LastAccessTimeUtc descending + select candidateFileInfo; + + var invalidPayloadFilesToDelete = WhereCumulativeSizeGreaterThan(orderedFileInfos, maxNumberOfBytesToRetain); + + foreach (var fileToDelete in invalidPayloadFilesToDelete) + { + try + { + fileToDelete.Delete(); + } + catch (Exception ex) + { + SelfLog.WriteLine("Exception '{0}' thrown while trying to delete file {1}", ex.Message, fileToDelete.FullName); + } + } + } + + private IEnumerable GetListOfEvents(string currentFile, ref long nextLineBeginsAtOffset, ref int count) + { + List events = new List(); + + using (var current = IOFile.Open(currentFile, FileMode.Open, FileAccess.Read, FileShare.ReadWrite)) + { + current.Position = nextLineBeginsAtOffset; + + string nextLine; + while (count < _batchPostingLimit && + TryReadLine(current, ref nextLineBeginsAtOffset, out nextLine)) + { + // Count is the indicator that work was done, so advances even in the (rare) case an + // oversized event is dropped. + ++count; + + if (_eventBodyLimitBytes.HasValue && Encoding.UTF8.GetByteCount(nextLine) > _eventBodyLimitBytes.Value) + { + SelfLog.WriteLine( + "Event JSON representation exceeds the byte size limit of {0} and will be dropped; data: {1}", + _eventBodyLimitBytes, nextLine); + } + else + { + events.Add(DeserializeEvent(nextLine)); + } + } + } + + return events; + } + + private LogglyEvent DeserializeEvent(string eventLine) + { + return _serializer.Deserialize(new JsonTextReader(new StringReader(eventLine))); + } + + private void SerializeLogglyEventsToWriter(IEnumerable events, TextWriter writer) + { + foreach (var logglyEvent in events) + { + _serializer.Serialize(writer, logglyEvent); + writer.WriteLine(); + } + } + + static bool IsUnlockedAtLength(string file, long maxLen) + { + try + { + using (var fileStream = IOFile.Open(file, FileMode.OpenOrCreate, FileAccess.ReadWrite, FileShare.Read)) + { + return fileStream.Length <= maxLen; + } + } +#if HRESULTS + catch (IOException ex) + { + var errorCode = Marshal.GetHRForException(ex) & ((1 << 16) - 1); + if (errorCode != 32 && errorCode != 33) + { + SelfLog.WriteLine("Unexpected I/O exception while testing locked status of {0}: {1}", file, ex); + } + } +#else + catch (IOException) + { + // Where no HRESULT is available, assume IOExceptions indicate a locked file + } +#endif + catch (Exception ex) + { + SelfLog.WriteLine("Unexpected exception while testing locked status of {0}: {1}", file, ex); + } + + return false; + } + + static void WriteBookmark(FileStream bookmark, long nextLineBeginsAtOffset, string currentFile) + { + using (var writer = new StreamWriter(bookmark)) + { + writer.WriteLine("{0}:::{1}", nextLineBeginsAtOffset, currentFile); + } + } + + // It would be ideal to chomp whitespace here, but not required. + static bool TryReadLine(Stream current, ref long nextStart, out string nextLine) + { + var includesBom = nextStart == 0; + + if (current.Length <= nextStart) + { + nextLine = null; + return false; + } + + current.Position = nextStart; + + // Important not to dispose this StreamReader as the stream must remain open. + var reader = new StreamReader(current, Encoding.UTF8, false, 128); + nextLine = reader.ReadLine(); + + if (nextLine == null) + return false; + + nextStart += Encoding.UTF8.GetByteCount(nextLine) + Encoding.UTF8.GetByteCount(Environment.NewLine); + if (includesBom) + nextStart += 3; + + return true; + } + + static void TryReadBookmark(Stream bookmark, out long nextLineBeginsAtOffset, out string currentFile) + { + nextLineBeginsAtOffset = 0; + currentFile = null; + + if (bookmark.Length != 0) + { + // Important not to dispose this StreamReader as the stream must remain open. + var reader = new StreamReader(bookmark, Encoding.UTF8, false, 128); + var current = reader.ReadLine(); + + if (current != null) + { + bookmark.Position = 0; + var parts = current.Split(new[] { ":::" }, StringSplitOptions.RemoveEmptyEntries); + if (parts.Length == 2) + { + nextLineBeginsAtOffset = long.Parse(parts[0]); + currentFile = parts[1]; + } + } + + } + } + + string[] GetFileSet() + { + return Directory.GetFiles(_logFolder, _candidateSearchPath) + .OrderBy(n => n) + .ToArray(); + } + } +} + +#endif diff --git a/src/Serilog.Sinks.Loggly/Sinks/Loggly/LogEventConverter.cs b/src/Serilog.Sinks.Loggly/Sinks/Loggly/LogEventConverter.cs new file mode 100644 index 0000000..990b5a2 --- /dev/null +++ b/src/Serilog.Sinks.Loggly/Sinks/Loggly/LogEventConverter.cs @@ -0,0 +1,84 @@ +using System; +using System.Collections.Generic; +using System.Linq; +using System.Threading.Tasks; +using Loggly; +using SyslogLevel = Loggly.Transports.Syslog.Level; +using Loggly.Config; +using Serilog.Debugging; +using Serilog.Events; + +namespace Serilog.Sinks.Loggly.Sinks.Loggly +{ + /// + /// Converts Serilog's Log Event to loogly-csharp LogglyEvent + /// method was in LogglySink originally + /// + public class LogEventConverter + { + private readonly IFormatProvider _formatProvider; + + public LogEventConverter(IFormatProvider formatProvider = null) + { + _formatProvider = formatProvider; + } + + public LogglyEvent CreateLogglyEvent(LogEvent logEvent) + { + var logglyEvent = new LogglyEvent() { Timestamp = logEvent.Timestamp }; + + var isHttpTransport = LogglyConfig.Instance.Transport.LogTransport == LogTransport.Https; + logglyEvent.Syslog.Level = ToSyslogLevel(logEvent); + + logglyEvent.Data.AddIfAbsent("Message", logEvent.RenderMessage(_formatProvider)); + + foreach (var key in logEvent.Properties.Keys) + { + var propertyValue = logEvent.Properties[key]; + var simpleValue = LogglyPropertyFormatter.Simplify(propertyValue); + logglyEvent.Data.AddIfAbsent(key, simpleValue); + } + + if (isHttpTransport) + { + // syslog will capture these via the header + logglyEvent.Data.AddIfAbsent("Level", logEvent.Level.ToString()); + } + + if (logEvent.Exception != null) + { + logglyEvent.Data.AddIfAbsent("Exception", logEvent.Exception); + } + return logglyEvent; + } + + + static SyslogLevel ToSyslogLevel(LogEvent logEvent) + { + SyslogLevel syslogLevel; + // map the level to a syslog level in case that transport is used. + switch (logEvent.Level) + { + case LogEventLevel.Verbose: + case LogEventLevel.Debug: + syslogLevel = SyslogLevel.Notice; + break; + case LogEventLevel.Information: + syslogLevel = SyslogLevel.Information; + break; + case LogEventLevel.Warning: + syslogLevel = SyslogLevel.Warning; + break; + case LogEventLevel.Error: + case LogEventLevel.Fatal: + syslogLevel = SyslogLevel.Error; + break; + default: + SelfLog.WriteLine("Unexpected logging level, writing to loggly as Information"); + syslogLevel = SyslogLevel.Information; + break; + } + return syslogLevel; + } + } +} diff --git a/src/Serilog.Sinks.Loggly/Sinks/Loggly/LogglyFormatter.cs b/src/Serilog.Sinks.Loggly/Sinks/Loggly/LogglyFormatter.cs new file mode 100644 index 0000000..bf8f0e5 --- /dev/null +++ b/src/Serilog.Sinks.Loggly/Sinks/Loggly/LogglyFormatter.cs @@ -0,0 +1,40 @@ +// Serilog.Sinks.Seq Copyright 2016 Serilog Contributors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +using System.IO; +using Newtonsoft.Json; +using Serilog.Events; +using Serilog.Formatting; +using Serilog.Sinks.Loggly.Sinks.Loggly; + +namespace Serilog.Sinks.Loggly +{ + /// + /// Formatter for the JSON schema accepted by Loggly's /bulk endpoint. + /// + class LogglyFormatter : ITextFormatter + { + readonly JsonSerializer _serializer = JsonSerializer.Create(); + readonly LogEventConverter _converter = new LogEventConverter(null); + + public void Format(LogEvent logEvent, TextWriter output) + { + //Serializing the LogglyEvent means we can work with it from here on out and + // avoid the serialization / deserialization troubles serilog's logevent + // currently poses. + _serializer.Serialize(output, _converter.CreateLogglyEvent(logEvent)); + output.WriteLine(); //adds the necessary linebreak + } + } +} diff --git a/src/Serilog.Sinks.Loggly/Sinks/Loggly/LogglySink.cs b/src/Serilog.Sinks.Loggly/Sinks/Loggly/LogglySink.cs index 63715c6..30748dd 100644 --- a/src/Serilog.Sinks.Loggly/Sinks/Loggly/LogglySink.cs +++ b/src/Serilog.Sinks.Loggly/Sinks/Loggly/LogglySink.cs @@ -17,11 +17,9 @@ using System.Linq; using System.Threading.Tasks; using Loggly; -using Loggly.Config; -using Serilog.Debugging; using Serilog.Events; +using Serilog.Sinks.Loggly.Sinks.Loggly; using Serilog.Sinks.PeriodicBatching; -using SyslogLevel=Loggly.Transports.Syslog.Level; namespace Serilog.Sinks.Loggly { @@ -30,8 +28,8 @@ namespace Serilog.Sinks.Loggly /// public class LogglySink : PeriodicBatchingSink { - readonly IFormatProvider _formatProvider; - LogglyClient _client; + private readonly LogEventConverter _converter; + private readonly LogglyClient _client; /// /// A reasonable default for the number of events posted in @@ -53,9 +51,8 @@ public class LogglySink : PeriodicBatchingSink public LogglySink(IFormatProvider formatProvider, int batchSizeLimit, TimeSpan period) : base (batchSizeLimit, period) { - _formatProvider = formatProvider; - _client = new LogglyClient(); + _converter = new LogEventConverter(formatProvider); } /// @@ -66,64 +63,8 @@ public LogglySink(IFormatProvider formatProvider, int batchSizeLimit, TimeSpan p /// not both. protected override async Task EmitBatchAsync(IEnumerable events) { - await _client.Log(events.Select(CreateLogglyEvent)); - } - - private LogglyEvent CreateLogglyEvent(LogEvent logEvent) - { - var logglyEvent = new LogglyEvent() { Timestamp = logEvent.Timestamp }; - - var isHttpTransport = LogglyConfig.Instance.Transport.LogTransport == LogTransport.Https; - logglyEvent.Syslog.Level = ToSyslogLevel(logEvent); - - logglyEvent.Data.AddIfAbsent("Message", logEvent.RenderMessage(_formatProvider)); - - foreach (var key in logEvent.Properties.Keys) - { - var propertyValue = logEvent.Properties[key]; - var simpleValue = LogglyPropertyFormatter.Simplify(propertyValue); - logglyEvent.Data.AddIfAbsent(key, simpleValue); - } - - if (isHttpTransport) - { - // syslog will capture these via the header - logglyEvent.Data.AddIfAbsent("Level", logEvent.Level.ToString()); - } - - if (logEvent.Exception != null) - { - logglyEvent.Data.AddIfAbsent("Exception", logEvent.Exception); - } - return logglyEvent; - } - - static SyslogLevel ToSyslogLevel(LogEvent logEvent) - { - SyslogLevel syslogLevel; - // map the level to a syslog level in case that transport is used. - switch (logEvent.Level) - { - case LogEventLevel.Verbose: - case LogEventLevel.Debug: - syslogLevel = SyslogLevel.Notice; - break; - case LogEventLevel.Information: - syslogLevel = SyslogLevel.Information; - break; - case LogEventLevel.Warning: - syslogLevel = SyslogLevel.Warning; - break; - case LogEventLevel.Error: - case LogEventLevel.Fatal: - syslogLevel = SyslogLevel.Error; - break; - default: - SelfLog.WriteLine("Unexpected logging level, writing to loggly as Information"); - syslogLevel = SyslogLevel.Information; - break; - } - return syslogLevel; + await _client.Log(events.Select(_converter.CreateLogglyEvent)); } + } } diff --git a/src/Serilog.Sinks.Loggly/Sinks/Loggly/PortableTimer.cs b/src/Serilog.Sinks.Loggly/Sinks/Loggly/PortableTimer.cs new file mode 100644 index 0000000..96189cf --- /dev/null +++ b/src/Serilog.Sinks.Loggly/Sinks/Loggly/PortableTimer.cs @@ -0,0 +1,139 @@ +// Copyright 2013-2016 Serilog Contributors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +using Serilog.Debugging; +using System; +using System.Threading; +using System.Threading.Tasks; + +namespace Serilog.Sinks.Loggly +{ + class PortableTimer : IDisposable + { + readonly object _stateLock = new object(); + + readonly Func _onTick; + readonly CancellationTokenSource _cancel = new CancellationTokenSource(); + +#if THREADING_TIMER + readonly Timer _timer; +#endif + + bool _running; + bool _disposed; + + public PortableTimer(Func onTick) + { + if (onTick == null) throw new ArgumentNullException(nameof(onTick)); + + _onTick = onTick; + +#if THREADING_TIMER + _timer = new Timer(_ => OnTick(), null, Timeout.Infinite, Timeout.Infinite); +#endif + } + + public void Start(TimeSpan interval) + { + if (interval < TimeSpan.Zero) throw new ArgumentOutOfRangeException(nameof(interval)); + + lock (_stateLock) + { + if (_disposed) + throw new ObjectDisposedException(nameof(PortableTimer)); + +#if THREADING_TIMER + _timer.Change(interval, Timeout.InfiniteTimeSpan); +#else + Task.Delay(interval, _cancel.Token) + .ContinueWith( + _ => OnTick(), + CancellationToken.None, + TaskContinuationOptions.DenyChildAttach, + TaskScheduler.Default); +#endif + } + } + + async void OnTick() + { + try + { + lock (_stateLock) + { + if (_disposed) + { + return; + } + + // There's a little bit of raciness here, but it's needed to support the + // current API, which allows the tick handler to reenter and set the next interval. + + if (_running) + { + Monitor.Wait(_stateLock); + + if (_disposed) + { + return; + } + } + + _running = true; + } + + if (!_cancel.Token.IsCancellationRequested) + { + await _onTick(_cancel.Token); + } + } + catch (OperationCanceledException tcx) + { + SelfLog.WriteLine("The timer was canceled during invocation: {0}", tcx); + } + finally + { + lock (_stateLock) + { + _running = false; + Monitor.PulseAll(_stateLock); + } + } + } + + public void Dispose() + { + _cancel.Cancel(); + + lock (_stateLock) + { + if (_disposed) + { + return; + } + + while (_running) + { + Monitor.Wait(_stateLock); + } + +#if THREADING_TIMER + _timer.Dispose(); +#endif + + _disposed = true; + } + } + } +} diff --git a/src/Serilog.Sinks.Loggly/project.json b/src/Serilog.Sinks.Loggly/project.json index ce121bf..1bd6c7e 100644 --- a/src/Serilog.Sinks.Loggly/project.json +++ b/src/Serilog.Sinks.Loggly/project.json @@ -12,16 +12,31 @@ "loggly-csharp": "4.6.0.5", "Newtonsoft.Json": "9.0.1", "Serilog": "2.0.0", - "Serilog.Sinks.PeriodicBatching": "2.0.0" + "Serilog.Sinks.PeriodicBatching": "2.0.0", + "Serilog.Sinks.File": "3.1.1", + "Serilog.Sinks.RollingFile": "3.2.0" }, "buildOptions": { "keyFile": "../../assets/Serilog.snk" }, "frameworks": { - "net45": { + "net4.5": { + "buildOptions": { + "define": [ "DURABLE", "THREADING_TIMER", "HRESULTS" ] + }, + "frameworkAssemblies": { + "System.Net.Http": "" + }, + "dependencies": { + } }, "netstandard1.5": { + "buildOptions": { + "define": [ "DURABLE", "THREADING_TIMER" ] + }, "dependencies": { + "System.Net.Http": "4.1.0", + "System.Threading.Timer": "4.0.1" } } }