Keep Current.Logger = {Umbraco.Core.Logging.Serilog.SerilogLogger} unless specifically changed

[hfloyd]

I'm not sure if this is a bug or a feature request... So feel free to reclassify...

In my project, I have a custom "WebControllerBase : SurfaceController, IRenderMvcController" and then a "public class DefaultController : WebControllerBase" which wraps the Model with some extra stuff and swaps the View. (This is set to run for all page requests via a "Startup : IUserComposer" with composition.SetDefaultRenderMvcController(typeof(DefaultController));)

The problem I have noticed is that this changes the type of Current.Logger from {Umbraco.Core.Logging.Serilog.SerilogLogger} (which DOES log as expected to Serilog, and is visible in the LogViewer) to {Umbraco.Core.Logging.DebugDiagnosticsLogger} (which DOES NOT log as expected).

I'm not exactly sure why this gets changed, or where/how I could set it back to {Umbraco.Core.Logging.Serilog.SerilogLogger}. I want to be able to use logging in my View files.

Bug summary

By using a custom controller, and without explicitly implementing a different logger, default logging via Current.Logger stops working. There are no compilation errors or warnings about this logged anywhere, it just doesn't log anything to Serilog.

Steps to reproduce

1. Create a custom controller "DefaultController: SurfaceController, IRenderMvcController". It doesn't need to do anything specific that is different from default behavior. Ex:

public override ActionResult Index(ContentModel model)
       {
           return base.CurrentTemplate(model);
       }

2. Make it the default controller via an IUserComposer with composition.SetDefaultRenderMvcController(typeof(DefaultController));
3. Create a View for a Doctype, Add some code to do some test logging:

@using Umbraco.Core.Composing
@using Umbraco.Core.Logging
@inherits Umbraco.Web.Mvc.UmbracoViewPage<IPublishedContent>
@{
    Layout = null; 
    //Test logging
    var page = Umbraco.AssignedContentItem.Name;
    var tempError = new Exception("Just a fake error!");
    Current.Logger.Error<UmbracoViewPage<IPublishedContent>>(tempError, "1 - TEST ERROR on '{Page}'", page);
     Current.Logger.Info<UmbracoViewPage<IPublishedContent>>("2 - TEST on '{Page}'", page);
}

4. Run the page.
5. Check the LogViewer. You won't see your log entries.

Expected result

I would expect that unless I specifically set a different logger, that all my Controllers and Views (and Models) would utilize {Umbraco.Core.Logging.Serilog.SerilogLogger} so that logging works as expected.

Actual result

Custom log messages are not logged properly. Standard Umbraco.Core logs are still generated.

Related Forum Posts

• https://our.umbraco.com/forum/using-umbraco-and-getting-started//99591-use-of-currentlogger-in-umbracoviewpage-etc397
• https://our.umbraco.com/forum/umbraco-8/97996-bug-with-currentlogger-or-maybe-im-using-it-wrong

[hfloyd]

An additional note - As per the second Forum link, this issue makes it impossible to log from inside an IUserComposer

[hfloyd]

Mysteriously, when I added a private logging variable to my Controllers, the Views now log properly. I don't understand Dependency Injection very well, so perhaps this isn't magical to anyone else, but if this is intended/expected behavior, perhaps we just need to add it to the documentation somewhere?

public abstract class WebControllerBase : SurfaceController, IRenderMvcController
    {
        private readonly ILogger _logger;

        public WebControllerBase(ILogger logger)
        {
            _logger = logger;
        }
...
}

public class DefaultController : WebControllerBase
    {
        private readonly ILogger _logger;
        public DefaultController(ILogger logger) : base(logger)
        {
            _logger = logger;
        }

 public override ActionResult Index(ContentModel model)
        {...}
}

[nul800sebastiaan]

Well that is a good find! I guess by injecting a specific logger you get the one you were expecting instead of DebugDiagnosticsLogger (which, I believe, is the miniprofiler logger).

I am not sure if this intentional behavior, I'll need to ask around. But if it is then it should be documented.

[anth12]

In the getter for Current.Logger, if _factory is not initialised, _logger is initialised as DebugDiagnosticsLogger:

Umbraco-CMS/src/Umbraco.Core/Composing/Current.cs

Lines 115 to 117 in c63af8e

	public static ILogger Logger
	=> _logger ?? (_logger = _factory?.TryGetInstance<ILogger>()
	?? new DebugDiagnosticsLogger());

This can happen when invoking Current.Logger.* before the Current.Factory setter has been called in CoreRuntime:

Umbraco-CMS/src/Umbraco.Core/Runtime/CoreRuntime.cs

Line 184 in d45ef63

_factory = Current.Factory = composition.CreateFactory();

In my case, we had a custom IUserComposer which was logging an application starting message- which seems to be executed before CoreRuntime.Boot.

The simple workaround is to avoid logging via Current.Logger during application startup, alternatively using Serliog directly will work Log.Logger.Information(...).

[umbrabot]

Hiya @hfloyd,

Just wanted to let you know that we noticed that this issue got a bit stale and might not be relevant any more.

We will close this issue for now but we're happy to open it up again if you think it's still relevant (for example: it's a feature request that's not yet implemented, or it's a bug that's not yet been fixed).

To open it this issue up again, you can write @umbrabot still relevant in a new comment as the first line. It would be super helpful for us if on the next line you could let us know why you think it's still relevant.

For example:

@umbrabot still relevant
This bug can still be reproduced in version x.y.z

This will reopen the issue in the next few hours.

Thanks, from your friendly Umbraco GitHub bot 🤖 🙂