Bye bye Log4Net, Hello Serilog #2845

warrenbuckley · 2018-08-10T15:23:35Z

This PR contains the initial configuration work of getting rid of Log4Net and swapping it out to use Serilog so we have better control of logging output with structured logs eventually; that's to come in a seperate PR

Things to look for

Try and check some of the following things

Ensure/verify all Log4Net files are gone & nothing left behind
Proof read the code changes here & shout if nothing is not clear
Install Umbraco from nupkg builkd outputs (Test Nupkg's install Serilog dependencies)

Testing Notes

The C# configured logged by default will generate two rolling log files (one for each day)

Same format of text file ouput
A JSON log file that includes all th extra meta-data/properties (Can be used to be imported to local copy of SEQ for querying)

Two config files have been added to configure the logger

config/serilog.config
config/serilog.user.config

See if you can experiment with the two configuration files with different values (See config & filtering sections below) to output the logs you require.

Importing the JSON log file into SEQ

Install SEQ locally on your machine for free
https://getseq.net

Use the CLEF (SEQ log import tool)
https://github.com/datalust/clef-tool/releases

Details on usage here
https://docs.getseq.net/docs/importing-log-files

Using a 3rd party Serilog Sink

There are many sinks available
https://github.com/serilog/serilog/wiki/Provided-Sinks

I recommend adding/installing PM> Install-Package Serilog.Sinks.Seq from Nuget then add the following to the serilog.user.config

<add key="serilog:using:Seq" value="Serilog.Sinks.Seq" />
<add key="serilog:write-to:Seq.serverUrl" value="http://localhost:5341" />

Config files

The config files uses serilog.Settings.AppSettings NuGet package & the project readme details some usage, however I have tried to put in some examples in the serilog.user.config file. That hopefuly gives some examples or usages on what could be put in here.

https://github.com/serilog/serilog-settings-appsettings

Filtering

Its possible for the user definied configuration to include or exclude logs based on expressions, but in the example I have shown how you would configure it so that all sinks definied in the user config will only log out messages that start with my namespace.

This is optional and could be removed alltogether. If the user wants to configure their sink to capture all of Umbraco logs AND any logs they are writing to the logger too.

https://github.com/serilog/serilog-filters-expressions

Configure/Overide logging

After a suggestion from @Shazwazza its now possible to configure Serilog in code if that is easier than trying to configure a complex Serilog pipeline only via the serilog.user.config file.

Example that developers coulld implement (instead of serilog.user.config)

using Serilog;
using Serilog.Filters;
using Umbraco.Core.Logging;
using Umbraco.Core.Logging.SerilogExtensions;
using Umbraco.Web;
using ILogger = Umbraco.Core.Logging.ILogger;

namespace MyNamespace
{
    public class WarrensLogging : UmbracoApplication
    {
        protected override ILogger GetLogger()
        {
            //Example of building my own logger configuration
            var loggerConfig = new LoggerConfiguration();
            loggerConfig.MinimalConfiguration()
                .OutputDefaultJsonFile()
                .Enrich.WithProperty("Environment", "Warrens-Test-UPDATED")
                .WriteTo.Logger(lc =>
                    lc.OutputDefaultTextFile()
                        .Filter.ByExcluding(Matching.FromSource("Umbraco.Web"))
                );
            
            return new Logger(loggerConfig);
        }
    }
}

Update Global.asax

Then they will need to update the Global.asax file like so
<%@ Application Inherits="MyNamespace.WarrensLogging" Language="C#" %>

Any Questions?

Anything doesn't make sense or is not clear leave a comment & I will try my best to describe what is going on.

Removes references to Log4Net from Web.Config's

…4Net further

…k we use

… build output happy

…ckages Removes AppDomainTokenConvertor - as we can add to SeriLog via a custom Enrich Property

…h Serilog CloseAndFlush- not 100% sure we need to do this as think LightInject tears it down nicely

…ckage & a custom one for the AppDomainAppId

…o Log4Net Unsure about the methods that take in args - have commented these out for now (Need to talk with Seb or Stephan about this)

…w file

…only diff currently is the log level type in the log file) Ensures we use the calling type in the Umbraco ILogger and passes it onto Serilog

# Conflicts: # src/Umbraco.Web.UI/web.Template.Debug.config

Configured to read from a custom .config file location as opposed to root web.config appsettings Enable Serilog Debugging aka Selflog

…nuked earlier

…LEF format so that it can be imported into a local copy of SEQ to help with filtering/finding log items

…ig can use it to save files with a relative path

… invoked

…template so its more in sync with Serilog signature & was an easy way to find some more logs I missed too

Shazwazza

Wow! epic PR, i've left some comments/questions... mostly minor stuff

Shazwazza · 2018-08-23T09:42:07Z

build/NuSpecs/tools/install.core.ps1

@@ -33,7 +33,6 @@ if ($project) {
 		robocopy $umbracoBinFolder $umbracoBinBackupPath /e /LOG:$copyLogsPath\UmbracoBinBackup.log

 		# Delete files Umbraco ships with
-		if(Test-Path $umbracoBinFolder\log4net.dll) { Remove-Item $umbracoBinFolder\log4net.dll -Force -Confirm:$false }


I'm not quite sure what this does and if we need it in v8 but if we do doesn't all the serilog DLLs need to be in here too? Might need to ask seb about that

I think this was related to when we were shipping a custom Log4Net DLL as Serilog will be a nupkg dependancy reference.

Any thoughts @nul800sebastiaan

OK after a quick slack chat with Seb this is fine & was a specific hack to Log4Net. So should all be good @Shazwazza

Shazwazza · 2018-08-23T09:55:41Z

src/Umbraco.Core/Logging/ImageProcessorLogger.cs

@@ -27,7 +27,7 @@ public void Log<T>(string text, [CallerMemberName] string callerName = null, [Ca
        {
            // Using LogHelper since the ImageProcessor logger expects a parameterless constructor.
            var message = $"{callerName} {lineNumber} : {text}";
-            Current.Logger.Error<T>(string.Empty, new ImageProcessingException(message));
+            Current.Logger.Error<T>(new ImageProcessingException(message), string.Empty);


We should make an extension method for Error to be able to pass in just an exception which in turn will pass in an empty string to the real method.

Shazwazza · 2018-08-23T09:58:40Z

src/Umbraco.Core/Logging/OwinLogger.cs

                    return true;
                case TraceEventType.Error:
-                    _logger.Error(_type.Value, string.Format("Event Id: {0}, state: {1}", eventId, state), exception ?? new Exception("Error"));
+                    _logger.Error(_type.Value, exception ?? new Exception("Error"), "[{EventType}] Event Id: {EventId}, State: {State}", eventType, eventId, state);


Maybe have an extension method for error that allows us to just pass in a message and it will create the underlying exception?

Shazwazza · 2018-08-23T09:59:02Z

src/Umbraco.Core/Logging/SerilogExtensions/Log4NetLevelMapperEnricher.cs

+    /// This is used to create a new property in Logs called 'Log4NetLevel'
+    /// So that we can map Serilog levels to Log4Net levels - so log files stay consistent
+    /// </summary>
+    public class Log4NetLevelMapperEnricher : ILogEventEnricher


make internal?

Yep just a bad habit of mine that I make everything public - will fix up

Shazwazza · 2018-08-23T10:00:57Z

src/Umbraco.Core/Models/Member.cs

-                + $" but the {logPropertyAlias} property does not exist on the member type so a default value is returned. Ensure that you have a property type with alias: "
-                + logPropertyAlias + $" configured on your member type in order to use the '{logPropertyName}' property on the model correctly.");
+            {
+                //WB: TODO Check that we do not need to specify properties again if used later on again in message template


Does this TODO still need a follow up?

I need to test this out - will check & verify

Shazwazza · 2018-08-23T10:01:53Z

src/Umbraco.Core/Persistence/Repositories/Implement/ContentTypeRepository.cs

-                var e = new Exception(m);
-                Logger.Error<ContentTypeRepository>(m, e);
+                var e = new Exception($"ContentType '{entity.Name}' cannot have an empty Alias. This is most likely due to invalid characters stripped from the Alias.");
+                Logger.Error<ContentTypeRepository>(e, "ContentType '{EntityName}' cannot have an empty Alias. This is most likely due to invalid characters stripped from the Alias.", entity.Name);


Another case where we could have an extension method to just pass in a message

Shazwazza · 2018-08-23T10:03:30Z

src/Umbraco.Core/Persistence/Repositories/Implement/ContentTypeRepositoryBase.cs

-                var m = $"Property Type '{pt.Name}' cannot have an empty Alias. This is most likely due to invalid characters stripped from the Alias.";
-                var e = new InvalidOperationException(m);
-                Logger.Error<ContentTypeRepositoryBase<TEntity>>(m, e);
+                var e = new InvalidOperationException($"Property Type '{pt.Name}' cannot have an empty Alias. This is most likely due to invalid characters stripped from the Alias.");


Another case where we could have an extension method to just pass in a message ? this ones is a little more tricky with the typed exception and the message formatting, but might work somehow?

Shazwazza · 2018-08-23T10:05:47Z

src/Umbraco.Core/UmbracoApplicationBase.cs

+
+            //Not sure if we need to do this - as my POC approach I never had to deal with this
+            //As the LightInject container when tearing down will dispose of Serilog AFAIK
+            Log.CloseAndFlush();


If it doesn't crash anything then might be better to just have it. Is it also IDisposable? i.e. would calling .Dispose() do the same thing?

Yes the logger itself is IDisposable AFAIK and hence my comment/note to say that I am not 100% sure if we need to keep in this explicit call to Log.CloseAndFlush()

Shazwazza · 2018-08-23T10:08:18Z

src/Umbraco.Tests/Composing/TypeFinderTests.cs

@@ -356,7 +356,6 @@ internal static IEnumerable<Assembly> GetBinAssemblies()
                    "Dynamic,",
                    "HtmlDiff,",
                    "Iesi.Collections,",
-                    "log4net,",


serilog should be added here, you'd want to put Serilog. with the dot as i think that means anything that starts with serilog will be ignored

Shazwazza · 2018-08-23T10:17:03Z

src/Umbraco.Web/WebApi/UnhandledExceptionLogger.cs

@@ -29,7 +29,10 @@ public override void Log(ExceptionLoggerContext context)
                && context.ExceptionContext.ActionContext.ControllerContext.Controller != null
                && context.Exception != null)
            {
-                _logger.Error(context.ExceptionContext.ActionContext.ControllerContext.Controller.GetType(), "Unhandled controller exception occurred", context.Exception);
+                var requestUrl = context.ExceptionContext.ControllerContext.Request.RequestUri.AbsoluteUri;


Prob need to do some null checks on this (can use ?.) since i think there might be cases where it's null

…add an empty string for the message

… contains only an ex - and under the hood it will pass on an empty string to the message

…t 0,1 etc- check & verified all good :)

…ion filters

…th params

Shazwazza · 2018-08-27T06:59:09Z

@warrenbuckley everything looks good from my tests, only a couple more comments about the ILogger changes:

For Error on the ILogger interface, maybe we shouldn't have either of these: void Error(Type reporting, Exception exception) + void Error(Type reporting, string message) and instead just have those signatures as extension methods ... then it would be required by the ILogger method void Error(Type reporting, Exception exception, string message) to deal with null values for either exception and message ?
Update the Fatal implementation in the same manner, we'd just leave the ILogger method void Fatal(Type reporting, Exception exception, string message) but it can deal with having null passed for either exception or message and we have extension methods to allow the user to pass in one or the other

What do you think?

…e error so all logger code goes from Fatal -> Verbose

… type

Shazwazza

I'm gonna go ahead and merge this, all looks good, i've fixed up some small things.

Shazwazza · 2018-08-24T02:28:37Z

src/Umbraco.Core/Logging/DisposableTimer.cs

@@ -38,16 +38,17 @@ internal enum LogType
            _endMessage = endMessage;
            _failMessage = failMessage;
            _thresholdMilliseconds = thresholdMilliseconds < 0 ? 0 : thresholdMilliseconds;
+            _timingId = Guid.NewGuid();


I think the timing ID should not include spaces so that when you are viewing the log and you double click on one of these IDs, it will highlight the entire thing which means it will also highlight the other affiliated log entries. So should be Guid.NewGuid.ToString("N") and change _timingId to a string

Shazwazza · 2018-08-28T05:38:44Z

src/Umbraco.Core/Logging/Logger.cs

-            if (logger == null || logger.IsWarnEnabled == false) return;
-            logger.Warn(format);
+            var logger = Log.Logger;
+            logger?.Warning(format);


This is incorrect as it doesn't take into account the type, I've fixed up in the latest commit

Shazwazza · 2018-08-28T05:48:59Z

@warrenbuckley We could simplify the ILogger interface to just:

void Fatal(Type reporting, Exception exception, string messageTemplate, params object[] propertyValues);

void Error(Type reporting, Exception exception, string messageTemplate, params object[] propertyValues);

void Warn(Type reporting, Exception exception, string messageTemplate, params object[] propertyValues);

void Info(Type reporting, string messageTemplate, params object[] propertyValues);

void Debug(Type reporting, string messageTemplate, params object[] propertyValues);

void Verbose(Type reporting, string messageTemplate, params object[] propertyValues);

For Fatal, Error, and Warn it can be expected that the implementer deals with null values for either Message or Exception which is what you implementation is already doing.

... But then I realized that this is the meaning of "Leaky abstraction" in that now the implementer and consumer need to be aware of the implementation details.

So i think the only changes needed would be to add additional ILogger methods for Fatal to allow for the same logic as Error.

I've pushed a commit with those changes.

I found another issue that i pushed a change for since Warn wasn't taking into account the Type in some cases, example:

2018-08-28 15:25:31,993 [P21164/D2/T12] WARN    - Umbraco has no content

Another thing I've noticed is that a new log file is created when a new AppDomain starts up. This is a known issue: serilog/serilog#380

So i'm not going to merge this in just yet! ... i think we need to solve this issue first.

…p restarts we don't get _001 or _002 files etc

…nd examples on what can be setup & configured

warrenbuckley · 2018-08-28T10:07:34Z

@Shazwazza updated the PR File Sink with the Shared property set to true and I can't reproduce the issue with the _01 and _02 etc appended files

Shazwazza · 2018-08-28T10:30:58Z

jaddie · 2018-08-29T06:02:10Z

I was going to join in the fun on this one until I realised that it was a branch I couldn't contribute to easily haha. Also I agree @Shazwazza I was thinking the same thing about the implementation etc having to care about null values. Although it could also be excused in that any decent logging platform (as Serilog says on their wiki) should handle invalid arguments being sent through as there is always unforseen situations with run-time which is the whole point of having logging in the first place to track down unexpected circumstances.

Warren added 30 commits July 27, 2018 13:48

Removes Log4Net NuGet packages & from our NuSpec's for Build scripts

20540d9

Removes the logic for the Log4Net binding redirect

e3be68d

Remove Log4Net from the Core Nuget package Install PowerShell script

6527abf

Remove log4net of the types/assemblies to ignore TypeFinding checking in

ac8d357

Remove Log4Net from Umbraco.Web.UI AssemblyInfo

dca7fb1

Log4Net config files removed from disk & CSProj

9dfe53f

Removes references to Log4Net from Web.Config's

Remove lots of classes that was specific to extending/configuring Log…

a3b018c

…4Net further

Rename init logger method to be non specific to what logging framewor…

182f72a

…k we use

Adds in Serilog core logging Nuget package to csproj & NuSpec to make…

9909add

… build output happy

Adds in Serilog.Enrichers.Process & Serilog.Enrichers.Thread Nuget Pa…

0826928

…ckages Removes AppDomainTokenConvertor - as we can add to SeriLog via a custom Enrich Property

Replaces Log4Net Shutdown in UmbracoAppBase Application_End event wit…

f6c02fb

…h Serilog CloseAndFlush- not 100% sure we need to do this as think LightInject tears it down nicely

Adds in Serilog & configures it to add in enrichers from the Nuget pa…

f6d81f3

…ckage & a custom one for the AppDomainAppId

Updates Logger class to implement & call Serilog methods as opposed t…

b774330

…o Log4Net Unsure about the methods that take in args - have commented these out for now (Need to talk with Seb or Stephan about this)

Adds Serilogs.Sink.File Nuget package

5659624

An initial test of seeing if Serilog is setup & can write out to a ne…

cf47fb9

…w file

Get logger to output as same file as old Log4Net and in same format (…

cd2a70a

…only diff currently is the log level type in the log file) Ensures we use the calling type in the Umbraco ILogger and passes it onto Serilog

Merge remote-tracking branch 'origin/temp8' into temp8-serilog

bee2c2d

# Conflicts: # src/Umbraco.Web.UI/web.Template.Debug.config

Adds in Serilog.Settings.AppSettings package

5cacdea

Configured to read from a custom .config file location as opposed to root web.config appsettings Enable Serilog Debugging aka Selflog

Merge remote-tracking branch 'origin/temp8' into temp8-serilog

b5f7285

After latest V8 merge - update the CSProj to remove the files that I …

045ece0

…nuked earlier

Adds in a new File sink - that will generate a JSON log file in the C…

e886086

…LEF format so that it can be imported into a local copy of SEQ to help with filtering/finding log items

Merge branch 'temp8' into temp8-serilog

216d01d

Adds an env variable (set to process level) so that the external conf…

81095fb

…ig can use it to save files with a relative path

Merge branch 'temp8' into temp8-serilog

998a7ff

Remove mention of Log4Net

a460d48

Removes mention of Log4Net & the commented code with it as it's never…

4392055

… invoked

Merge remote-tracking branch 'origin/temp8' into temp8-serilog

20d8139

Removes mention of Log4Net & removes commented out methods

0c36014

Remove log4net from Tests & Benchmark projects

8331abf

Remove log4net from the typefinder tests

aed9f77

Warren added 3 commits August 17, 2018 11:38

Adds the Fatal Logger Extension method <T>

3898418

Refactored the error params, so that exception is before the message/…

9e996c6

…template so its more in sync with Serilog signature & was an easy way to find some more logs I missed too

Add in MachineName as a Serilog property

3baf569

Shazwazza suggested changes Aug 23, 2018

View reviewed changes

Warren added 6 commits August 23, 2018 12:14

Adds new method to ILogger for taking only the exception - NOTE will …

66e4e1f

…add an empty string for the message

Make Log4NetLevel enricher internal - no need for it to be public

0c9ac7f

Add inline null checks as requested

219e8c7

Update ImageProcessorLogger - to use the new Error logger method that…

afebd88

… contains only an ex - and under the hood it will pass on an empty string to the message

Remove some //WB TODOs to check if the enum returns the string and no…

4070fc6

…t 0,1 etc- check & verified all good :)

Update ignore list for typefinder tests to include Serilog. in exclus…

224a7de

…ion filters

warrenbuckley removed the request for review from clausjensen August 23, 2018 11:58

Warren and others added 4 commits August 23, 2018 13:09

Verified the log output for genRef is all ok & remove TODO note

e17ba1c

Verified the log works correctly from my TODO note

fb4b0ce

Adds in Error without ex for just a message and a message template wi…

24f91f1

…th params

removes last log4net strings i can find

06d08e2

ghost assigned Shazwazza Aug 27, 2018

Shazwazza added 2 commits August 28, 2018 15:24

Adds additional Fatal methods to match Error and move Fatal code abov…

8d6e297

…e error so all logger code goes from Fatal -> Verbose

Simplifies logger calls to proxy all calls to a single method of it's…

6506abd

… type

Shazwazza approved these changes Aug 28, 2018

View reviewed changes

updates timing id

94cbe3b

Warren added 2 commits August 28, 2018 09:46

Adds the shared option to the File sink to avoid file locking & if ap…

34452e7

…p restarts we don't get _001 or _002 files etc

Comments out a lot of the serilog.user.config to give some guidance a…

91ab3b4

…nd examples on what can be setup & configured

Shazwazza merged commit a151829 into temp8 Aug 28, 2018

ghost removed the review label Aug 28, 2018

warrenbuckley deleted the temp8-serilog branch August 28, 2018 12:11

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Bye bye Log4Net, Hello Serilog #2845

Bye bye Log4Net, Hello Serilog #2845

warrenbuckley commented Aug 10, 2018 •

edited by Shazwazza

Loading

Shazwazza left a comment

Shazwazza Aug 23, 2018

warrenbuckley Aug 23, 2018

warrenbuckley Aug 23, 2018

Shazwazza Aug 23, 2018

Shazwazza Aug 23, 2018

Shazwazza Aug 23, 2018

warrenbuckley Aug 23, 2018

Shazwazza Aug 23, 2018

warrenbuckley Aug 23, 2018

Shazwazza Aug 23, 2018

Shazwazza Aug 23, 2018

Shazwazza Aug 23, 2018

warrenbuckley Aug 23, 2018

Shazwazza Aug 23, 2018

warrenbuckley Aug 23, 2018

Shazwazza Aug 23, 2018

Shazwazza commented Aug 27, 2018

Shazwazza left a comment

Shazwazza Aug 24, 2018

Shazwazza Aug 28, 2018

Shazwazza commented Aug 28, 2018

warrenbuckley commented Aug 28, 2018

Shazwazza commented Aug 28, 2018

jaddie commented Aug 29, 2018

Bye bye Log4Net, Hello Serilog #2845

Bye bye Log4Net, Hello Serilog #2845

Conversation

warrenbuckley commented Aug 10, 2018 • edited by Shazwazza Loading

Things to look for

Testing Notes

Importing the JSON log file into SEQ

Using a 3rd party Serilog Sink

Config files

Filtering

Configure/Overide logging

Example that developers coulld implement (instead of serilog.user.config)

Update Global.asax

Any Questions?

Shazwazza left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Shazwazza commented Aug 27, 2018

Shazwazza left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Shazwazza commented Aug 28, 2018

warrenbuckley commented Aug 28, 2018

Shazwazza commented Aug 28, 2018

jaddie commented Aug 29, 2018

warrenbuckley commented Aug 10, 2018 •

edited by Shazwazza

Loading