Serilog only logging the first time it is called after build

Question

I have an ASP NET MVC project which uses Ninject for IoC. Have added a Serilog logger

  public class LoggingModule : BaseModule
  {
    public override void Load()
    {
      var fileName = "c:\path\file.log";
      var loggerConfiguration = new LoggerConfiguration()
        .WriteTo.RollingFile(fileName, LogEventLevel.Debug)
        .MinimumLevel.Verbose();
      var logger = loggerConfiguration.CreateLogger();

      Log.Logger = logger;
      Bind<ILogger>().ToConstant(logger);
    }
  }

And am injecting this into a Controller.

When I exercise the code that uses it to log it will log once and then never again until I restart the web app.

I'm using the same configuration code (without ninject) in a windows service which works fine.

Versions installed are

<package id="Serilog" version="2.3.0" targetFramework="net45" />
<package id="Serilog.Sinks.File" version="3.1.0" targetFramework="net45" />
<package id="Serilog.Sinks.RollingFile" version="3.2.0" targetFramework="net45" />
<package id="Ninject" version="3.2.2.0" targetFramework="net45" />
<package id="Ninject.MVC3" version="3.2.1.0" targetFramework="net45" />
<package id="Ninject.Web.Common" version="3.2.3.0" targetFramework="net45" />
<package id="Ninject.Web.Common.WebHost" version="3.2.3.0" targetFramework="net45" />
<package id="Microsoft.AspNet.Mvc" version="5.2.3" targetFramework="net45" />

Update:

Following on from Caio's answer. I added in the SelfLog and see...

2016-11-22T14:29:25.6317957Z Caught exception while emitting to sink Serilog.Core.Sinks.RestrictedSink: System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'The rolling log file has been disposed.'.
   at Serilog.Sinks.RollingFile.RollingFileSink.Emit(LogEvent logEvent)
   at Serilog.Core.Sinks.SafeAggregateSink.Emit(LogEvent logEvent)

Update 2:

This turned out to be a bug in the way that IDependencyResolver had been implemented in our project. IDependencyResolver implements IDisposable and our implementation called dispose on the kernel. (Un?)luckily this had just never caused an issue before.

I've marked Caio's answer as the answer because him pointing me to the SelfLog gave me the tool to unwind what was happening. Thanks to all the helped though!

This question and answer - http://stackoverflow.com/questions/7395071/is-binding-toconstant-and-calling-insingletonscope-redundant - lead me to wonder if perhaps `InSingletonScope()` is necessary alongside `ToConstant()` in the Ninject version you're using.. Worth a try? — Nicholas Blumhardt, Nov 23 '16 at 02:36

C. Augusto Proiete · Accepted Answer · 2018-10-09T14:58:44.030

5

Have you tried checking the output from Serilog's self log, to see if there's any error occurring internally?

e.g.

Serilog.Debugging.SelfLog.Enable(msg => Console.WriteLine(msg));

https://github.com/serilog/serilog/wiki/Debugging-and-Diagnostics

edited Oct 09 '18 at 14:58

answered Nov 22 '16 at 14:22

C. Augusto Proiete

24,684
2
63
91

Ooh, I'd never seen that before! – Paul D'Ambra Nov 22 '16 at 14:27

score 1 · Answer 2 · answered Nov 22 '16 at 17:17

1

First question: Are you using one of the Ninject.MVC packages? If not, I'd try this first as they plug the Ninject container into the MVC pipeline correctly. https://www.nuget.org/packages/Ninject.MVC5/

Also: You can sometimes have an order-of-operations problem with DI containers. For this reason I find that it's unsafe to do much setup logic directly in the NinjectModule. I'd try something like this instead:

  Bind<ILogger>().ToMethod(context => {
  var fileName = "c:\path\file.log";
  var loggerConfiguration = new LoggerConfiguration()
    .WriteTo.RollingFile(fileName, LogEventLevel.Debug)
    .MinimumLevel.Verbose();
  var logger = loggerConfiguration.CreateLogger();

  Log.Logger = logger;
  }).In <whatever> Scope()

answered Nov 22 '16 at 17:17

Chris McKenzie

3,681
3
27
36

thanks, that's a step closer but it looks like Ninject was running the method every time even when set to singleton scope. There's a chance I've tried the same thing over and over again too many times though :) – Paul D'Ambra Nov 22 '16 at 17:45
1

It might be a big ask, but if you could put together a prototype project in github that displays the error, I could look into it for you. We do this all the time with log4net at my shop. – Chris McKenzie Nov 22 '16 at 21:10
if I can't solve it in the real app tomorrow. I'll have to do that anyway to see if I can isolate what's going on. Will share if that doesn't help me. – Paul D'Ambra Nov 22 '16 at 21:18
kk, let me know if you want to rope me in on that. You might have to tag me on twitter (@ISuperGeek) to get my attention. – Chris McKenzie Nov 23 '16 at 00:28

Serilog only logging the first time it is called after build

2 Answers2