ASP.NET MVC2 + Ninject + NLog (+ shared hosting?) = NullReferenceException

Question

I have an MVC2 app that's based on the Tekpub Starter Site, so it uses Ninject for dependency injection, NLog for logging, and a bunch of other libraries in various places. As far as I can tell though, it's these that are causing my problem.

Everything works beautifully on my PC using the ASP.NET dev server (Cassini) but when I deploy to the server (it's a cheap shared hosting deal), I get a NullReferenceException that seems to be related to Ninject instantiating the logger.

Here's the relevant bits of my Global.asax.cs

protected override void OnApplicationStarted() {
    Logger.Info("App is starting"); // <-- I think this is what's causing the problem

    RegisterRoutes(RouteTable.Routes);
    //MvcContrib.Routing.RouteDebugger.RewriteRoutesForTesting(RouteTable.Routes);
    RegisterAllControllersIn(Assembly.GetExecutingAssembly());
    SetEngines();
}

protected override IKernel CreateKernel() {
    return Container;
}

internal class SiteModule : NinjectModule {
    public override void Load() {
        Bind<ILogger>().To<NLogLogger>();
        // and a couple of others...
    }
}

protected void Application_End() {
    Logger.Info("App is shutting down");
}

protected void Application_Error() {
    Exception lastException = Server.GetLastError();
    Logger.Fatal(lastException);
}

public ILogger Logger {
    get {
        return Container.Get<ILogger>();
        }
    }
    static IKernel _container;
    public static IKernel Container {
        get {
            if (_container == null) {
                _container = new StandardKernel(new SiteModule());
            }
            return _container;
        }
    }

The nlog.config

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" >

    <targets>
        <!--Useful for debugging-->
        <target name="console" xsi:type="ColoredConsole"
         layout="${date:format=HH\:mm\:ss}|${level}|${stacktrace}|${message}" />

        <target name="file" xsi:type="File" fileName="${basedir}/App_Data/Site.log"
         layout="${date}: ${message}" />

        <target name="eventlog" xsi:type="EventLog" source="My App" log="Application"
        layout="${date}: ${message} ${stacktrace}" />

    </targets>

    <rules>
        <logger name="*" minlevel="Info" writeTo="file" />
        <!-- <logger name="*" minlevel="Fatal" writeTo="eventlog" /> -->
    </rules>
</nlog>

The NLogLogger class:

public class NLogLogger:ILogger {

    private Logger _logger;

    public NLogLogger() {
        _logger = LogManager.GetCurrentClassLogger();
    }

    public void Info(string message) {
        _logger.Info(message);
    }

    // similar for Warn, Debug, etc

Stack trace:

[NullReferenceException: Object reference not set to an instance of an object.]
   NLog.LogManager.GetCurrentClassLogger() +84
   DynamicInjector8cdfc2eb02f8497596a4704e379a4bb4(Object[] ) +40
   Ninject.Activation.Providers.StandardProvider.Create(IContext context) +319
   Ninject.Activation.Context.Resolve() +182
   Ninject.KernelBase.<Resolve>b__4(IContext context) +8
   System.Linq.<>c__DisplayClass12`3.<CombineSelectors>b__11(TSource x) +32
   System.Linq.WhereSelectEnumerableIterator`2.MoveNext() +151
   System.Linq.<CastIterator>d__b1`1.MoveNext() +92
   System.Linq.Enumerable.FirstOrDefault(IEnumerable`1 source) +4187840
   Ninject.ResolutionExtensions.Get(IResolutionRoot root, IParameter[] parameters) +149
   Web.Application.get_Logger() in C:\mvcstarter\Web\Global.asax.cs:159
   Web.Application.OnApplicationStarted() in C:\mvcstarter\Web\Global.asax.cs:80
   Ninject.Web.Mvc.NinjectHttpApplication.Application_Start() +535

[HttpException (0x80004005): Object reference not set to an instance of an object.]
   System.Web.HttpApplicationFactory.EnsureAppStartCalledForIntegratedMode(HttpContext context, HttpApplication app) +9024793
   System.Web.HttpApplication.RegisterEventSubscriptionsWithIIS(IntPtr appContext, HttpContext context, MethodInfo[] handlers) +131
   System.Web.HttpApplication.InitSpecial(HttpApplicationState state, MethodInfo[] handlers, IntPtr appContext, HttpContext context) +194
   System.Web.HttpApplicationFactory.GetSpecialApplicationInstance(IntPtr appContext, HttpContext context) +339
   System.Web.Hosting.PipelineRuntime.InitializeApplication(IntPtr appContext) +253

[HttpException (0x80004005): Object reference not set to an instance of an object.]
   System.Web.HttpRuntime.FirstRequestInit(HttpContext context) +8946484
   System.Web.HttpRuntime.EnsureFirstRequestInit(HttpContext context) +97
   System.Web.HttpRuntime.ProcessRequestNotificationPrivate(IIS7WorkerRequest wr, HttpContext context) +256

If I comment out the logging in OnApplicationStarted, I get a different exception. I'm not sure why it's happening, because there shouldn't be any logging happening so I'm not sure why it's trying to instantiate the logger.

[NullReferenceException: Object reference not set to an instance of an object.]
   NLog.LogManager.GetCurrentClassLogger() +84
   DynamicInjector5ca7d21cf56b4732957e22cb1bfd8bdd(Object[] ) +40
   Ninject.Activation.Providers.StandardProvider.Create(IContext context) +319
   Ninject.Activation.Context.Resolve() +182
   Ninject.KernelBase.<Resolve>b__4(IContext context) +8
   System.Linq.<>c__DisplayClass12`3.<CombineSelectors>b__11(TSource x) +32
   System.Linq.WhereSelectEnumerableIterator`2.MoveNext() +151
   System.Linq.Enumerable.FirstOrDefault(IEnumerable`1 source) +4187840
   Ninject.Planning.Targets.Target`1.ResolveWithin(IContext parent) +347
   Ninject.Activation.Providers.StandardProvider.GetValue(IContext context, ITarget target) +138
   Ninject.Activation.Providers.<>c__DisplayClass2.<Create>b__1(ITarget target) +17
   System.Linq.WhereSelectArrayIterator`2.MoveNext() +85
   System.Linq.Buffer`1..ctor(IEnumerable`1 source) +325
   System.Linq.Enumerable.ToArray(IEnumerable`1 source) +78
   Ninject.Activation.Providers.StandardProvider.Create(IContext context) +306
   Ninject.Activation.Context.Resolve() +182
   Ninject.KernelBase.<Resolve>b__4(IContext context) +8
   System.Linq.<>c__DisplayClass12`3.<CombineSelectors>b__11(TSource x) +32
   System.Linq.WhereSelectEnumerableIterator`2.MoveNext() +151
   System.Linq.<CastIterator>d__b1`1.MoveNext() +92
   System.Linq.Enumerable.FirstOrDefault(IEnumerable`1 source) +4187840
   Ninject.ResolutionExtensions.TryGet(IResolutionRoot root, String name, IParameter[] parameters) +261
   Ninject.Web.Mvc.NinjectControllerFactory.CreateController(RequestContext requestContext, String controllerName) +108
   System.Web.Mvc.MvcHandler.ProcessRequestInit(HttpContextBase httpContext, IController& controller, IControllerFactory& factory) +124
   System.Web.Mvc.MvcHandler.BeginProcessRequest(HttpContextBase httpContext, AsyncCallback callback, Object state) +50
   System.Web.Mvc.MvcHandler.BeginProcessRequest(HttpContext httpContext, AsyncCallback callback, Object state) +48
   System.Web.Mvc.MvcHandler.System.Web.IHttpAsyncHandler.BeginProcessRequest(HttpContext context, AsyncCallback cb, Object extraData) +16
   System.Web.Mvc.<>c__DisplayClass7.<BeginProcessRequest>b__6() +29
   System.Web.Mvc.ServerExecuteHttpHandlerWrapper.Wrap(Func`1 func) +38
   System.Web.Mvc.ServerExecuteHttpHandlerAsyncWrapper.BeginProcessRequest(HttpContext context, AsyncCallback cb, Object extraData) +97
   System.Web.HttpServerUtility.ExecuteInternal(IHttpHandler handler, TextWriter writer, Boolean preserveForm, Boolean setPreviousPage, VirtualPath path, VirtualPath filePath, String physPath, Exception error, String queryStringOverride) +1508
   System.Web.HttpServerUtility.Execute(IHttpHandler handler, TextWriter writer, Boolean preserveForm, Boolean setPreviousPage) +77
   System.Web.HttpServerUtility.Execute(IHttpHandler handler, TextWriter writer, Boolean preserveForm) +28
   System.Web.HttpServerUtilityWrapper.Execute(IHttpHandler handler, TextWriter writer, Boolean preserveForm) +22
   System.Web.Mvc.Html.ChildActionExtensions.ActionHelper(HtmlHelper htmlHelper, String actionName, String controllerName, RouteValueDictionary routeValues, TextWriter textWriter) +372
   System.Web.Mvc.Html.ChildActionExtensions.RenderAction(HtmlHelper htmlHelper, String actionName, String controllerName) +35
   ASP.views_home_index_aspx.__RenderContent2(HtmlTextWriter __w, Control parameterContainer) in c:\HostingSpaces\<snip>\wwwroot\Views\Home\Index.aspx:8
   System.Web.UI.Control.RenderChildrenInternal(HtmlTextWriter writer, ICollection children) +109
   System.Web.UI.Control.RenderChildren(HtmlTextWriter writer) +8
   System.Web.UI.Control.Render(HtmlTextWriter writer) +10
   System.Web.UI.Control.RenderControlInternal(HtmlTextWriter writer, ControlAdapter adapter) +27
   System.Web.UI.Control.RenderControl(HtmlTextWriter writer, ControlAdapter adapter) +100
   System.Web.UI.Control.RenderControl(HtmlTextWriter writer) +25
   ASP.views_shared_site_master.__Render__control1(HtmlTextWriter __w, Control parameterContainer) in c:\HostingSpaces\<snip>\wwwroot\Views\Shared\Site.Master:48
   System.Web.UI.Control.RenderChildrenInternal(HtmlTextWriter writer, ICollection children) +109
   System.Web.UI.Control.RenderChildren(HtmlTextWriter writer) +8
   System.Web.UI.Control.Render(HtmlTextWriter writer) +10
   System.Web.UI.Control.RenderControlInternal(HtmlTextWriter writer, ControlAdapter adapter) +27
   System.Web.UI.Control.RenderControl(HtmlTextWriter writer, ControlAdapter adapter) +100
   System.Web.UI.Control.RenderControl(HtmlTextWriter writer) +25
   System.Web.UI.Control.RenderChildrenInternal(HtmlTextWriter writer, ICollection children) +208
   System.Web.UI.Control.RenderChildren(HtmlTextWriter writer) +8
   System.Web.Mvc.ViewPage.Render(HtmlTextWriter writer) +55
   System.Web.UI.Control.RenderControlInternal(HtmlTextWriter writer, ControlAdapter adapter) +27
   System.Web.UI.Control.RenderControl(HtmlTextWriter writer, ControlAdapter adapter) +100
   System.Web.UI.Control.RenderControl(HtmlTextWriter writer) +25
   System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint) +3060

The only way I can get the site to work at all is to fake out the logger entirely, which I'm not at all happy with. This is my first time playing with ASP.NET shared hosting, so I'm a bit at a loss. Anyone have any helpful suggestions?

Leto

The answer below helped me out with a somewhat similar issue in WPF (please mark it as the answer!). However, for web development it saves odd debugging issues if you just start off with testing locally on IIS instead of Cassini - whatever gets your dev/testing/production environments as similar as possible saves grief in the long run. – Whitehead

Tha answer below also solves my problem: NLog + Ninject not working on Release mode when on Debug mode works ok. – Acantho

Answer 1

You could avoid using LogManager.GetCurrentClassLogger() and let Ninject resolve the current class name for you:

Change the constructor of your NLogLogger class into this:

public NLogLogger(string currentClassName) 
{
  _logger = LogManager.GetLogger(currentClassName);
}

And change the ninject binding to resolve the current classname:

Bind<ILogger>().To<NLogLogger>()
  .WithConstructorArgument("currentClassName", x => x.Request.ParentContext.Request.Service.FullName);

Additional benefit: your log file now also includes the class name from where the log directive was issued.

I know my answer is a little bit late to the party, but I was struggling with this myself today and couldn't find the answer anywhere. Maybe this helps someone else.

Killy

Your answer helped me figure out a StructureMap solution: #4519761 – Subtype

Thanks a lot Robin, it was really helpful. I've lost almost a day splitting my hair trying to figure out the cause of an error that I was getting only on Release mode – Fetich

Thanks. I was also getting this error only in Release build. – Theta

Answer 2

It looks like NLog can't run in medium trust: http://nlog-project.org/forum.html#nabble-td1685352

If you look in the Global, the app logs when it starts up as well as when it shuts down. You should be able to remove that and be happy.

Zimmermann

Answer 3

Shared hosting often has restrictions on reflection etc.

So my guess is that

[NullReferenceException: Object reference not set to an instance of an object.] NLog.LogManager.GetCurrentClassLogger() +84

is related to that - what happens if you get the logger using a meachanism where you pase in a Type that you get at compile time via typeof ?

Superimposed

One of the reasons I picked the host (apart from low price - non-profit group and everything) is that they supposedly don't have any restrictions on stuff like that. I'm also not an NLog guru by any means, but my understanding is the method you quoted is the way to use it, see nlog-project.org/wiki/Tutorial#Creating_loggers for example...I'll have a look into it when I get home... – Leto

@Jon: Like the rest of the planet, I've used my share of loggers (and to my shame written some). I've just used log4net and the builtin stuff on .NET, not NLog - but I have deep knowledge of how it works with lo4net and its all pretty analagous. Looking at the cited article, they have one where you pass a name and one where you dont. The one where you dont has to determine the name somehow -that somehow is Reflection. Some reflection (not all) is restricted in shared hosting. Therefore removing GetCurrentClassLogger from the equation can eliminate this possible cause from your inquiries. – Superimposed

Answer 4

I have experienced a similar problem.

My (simplistic) solution:

replace these lines

private Logger Logger = LogManager.GetCurrentClassLogger();

by this line

private static Logger Logger = LogManager.GetCurrentClassLogger();

The readonly keyword is optional.

Weightless