Log4net
  1. Log4net
  2. LOG4NET-342

Add a way to prevent silent failure

    Details

    • Type: New Feature New Feature
    • Status: Resolved
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 1.2.12
    • Component/s: None
    • Labels:
      None

      Description

      I spent most of the day trying to find out why logging is not working on my dev system but not on test. There should be a way to force error reporting by throwing (possibly unhandled) exceptions. This could be done by adding a required flag to the appenders and another flag that requires a least one working appender.

      I am not sure about a good way to implement this, I would just love it if my favourite tool to end silent failure could stop failing silently.

        Activity

        Hide
        Dominik Psenner added a comment - - edited

        One could add a global boolean configuration named like "EnableExceptionThrowing" that is "False" by default. In case one wants to test something he would then be able to change that flag in the app.config. Once set to "True" all exceptions thrown would no longer be ignored silently, but thrown up to the calling application so that the exception can be debugged/handled in some other way.

        I just targeted it for 1.2.12 since it should be doable.

        EDIT: have you tried to enable log4nets internal debugging as described at http://logging.apache.org/log4net/release/faq.html ? Let us know if that is enough for your usecase.

        Show
        Dominik Psenner added a comment - - edited One could add a global boolean configuration named like "EnableExceptionThrowing" that is "False" by default. In case one wants to test something he would then be able to change that flag in the app.config. Once set to "True" all exceptions thrown would no longer be ignored silently, but thrown up to the calling application so that the exception can be debugged/handled in some other way. I just targeted it for 1.2.12 since it should be doable. EDIT: have you tried to enable log4nets internal debugging as described at http://logging.apache.org/log4net/release/faq.html ? Let us know if that is enough for your usecase.
        Hide
        Joachim Zobel added a comment -

        Internal debugging did not give any output. Neither did running the app as local system to exclude permission problems.

        But actually I made this feature request because log4nets silent failing is according to my experience and according to what google finds a frequent problem.

        There is also the use case that it is better to have an app that fails than to have an app that acts without logging. The apache httpd is the major app I know that implements this.

        Show
        Joachim Zobel added a comment - Internal debugging did not give any output. Neither did running the app as local system to exclude permission problems. But actually I made this feature request because log4nets silent failing is according to my experience and according to what google finds a frequent problem. There is also the use case that it is better to have an app that fails than to have an app that acts without logging. The apache httpd is the major app I know that implements this.
        Hide
        Ron Grabowski added a comment -

        If I'm working in a web app and I can't get basic logging to work I'll do this:

        <appSettings>
        <add key="log4net.Internal.Debug" value="true"/>
        </appSettings>
        <system.diagnostics>
        <trace autoflush="true">
        <listeners>
        <add name="textWriterTraceListener"
        type="System.Diagnostics.TextWriterTraceListener"
        initializeData="c:\\path\\to\\application\\App_Data
        og4net.txt" />
        </listeners>
        </trace>
        </system.diagnostics>

        Starting with 1.2.11, configurators return an ICollection of LogLog messages:

        var errors = XmlConfigurator.Configure().Cast<LogLog>().Where(x => x.Prefix.Contains("ERROR"));

        In hindsight the configurators should maintained their current signatures and new methods added to return a strongly typed collection of real objects of a non-generic collection of our internal LogLog object. When I wrote the code I was more concerned with maintaining 1.x compatibility than making it easy for non-legacy apps to use new feature :-/

        Show
        Ron Grabowski added a comment - If I'm working in a web app and I can't get basic logging to work I'll do this: <appSettings> <add key="log4net.Internal.Debug" value="true"/> </appSettings> <system.diagnostics> <trace autoflush="true"> <listeners> <add name="textWriterTraceListener" type="System.Diagnostics.TextWriterTraceListener" initializeData="c:\\path\\to\\application\\App_Data og4net.txt" /> </listeners> </trace> </system.diagnostics> Starting with 1.2.11, configurators return an ICollection of LogLog messages: var errors = XmlConfigurator.Configure().Cast<LogLog>().Where(x => x.Prefix.Contains("ERROR")); In hindsight the configurators should maintained their current signatures and new methods added to return a strongly typed collection of real objects of a non-generic collection of our internal LogLog object. When I wrote the code I was more concerned with maintaining 1.x compatibility than making it easy for non-legacy apps to use new feature :-/
        Hide
        Joachim Zobel added a comment -

        I did try internal debugging as you describe it without any results. It was however an exceptionally hard case. I had missed to put Global.asax into the deploy package, which did the Configure() and lots of logging (DEBUG: Starting page ...).

        The Configure return value is actually very helpful in the common case of a confguration failure.

        There is however also the use case that application failure is considered peferrable to running without logging. Not sure if log4net wants to cover this.

        Thanks,
        Joachim

        Show
        Joachim Zobel added a comment - I did try internal debugging as you describe it without any results. It was however an exceptionally hard case. I had missed to put Global.asax into the deploy package, which did the Configure() and lots of logging (DEBUG: Starting page ...). The Configure return value is actually very helpful in the common case of a confguration failure. There is however also the use case that application failure is considered peferrable to running without logging. Not sure if log4net wants to cover this. Thanks, Joachim
        Hide
        Ron Grabowski added a comment -

        Not too difficult to stop your app from starting up if logging isn't configured:

        if (log.IsErrorEnabled == false)

        { throw new ConfigurationErrorsException("Log4net failed to initialize properly."); }
        Show
        Ron Grabowski added a comment - Not too difficult to stop your app from starting up if logging isn't configured: if (log.IsErrorEnabled == false) { throw new ConfigurationErrorsException("Log4net failed to initialize properly."); }
        Hide
        Dominik Psenner added a comment - - edited

        IsErrorEnabled is quite misleading at this point and depending on the logging configuration it can result to false negatives. I think a proper refactoring+some documentation could do a great favor there so that one can find:

        if(log.InitializationState == InitializationStates.INITIALIZED)
        // all fine

        Valid members of the InitializationStates enum could be "INITIALIZED", "IN_PROGRESS", "NOT_YET", "FAILED".

        Show
        Dominik Psenner added a comment - - edited IsErrorEnabled is quite misleading at this point and depending on the logging configuration it can result to false negatives. I think a proper refactoring+some documentation could do a great favor there so that one can find: if(log.InitializationState == InitializationStates.INITIALIZED) // all fine Valid members of the InitializationStates enum could be "INITIALIZED", "IN_PROGRESS", "NOT_YET", "FAILED".
        Hide
        Dominik Psenner added a comment -

        Oh, I just noticed that there is a "Configured" property in Hierarchy that could be wrapped in Logger like this:

        /// <summary>
        /// Gets the flag that indicates if the repository of this Logger has been configured.
        /// </summary>
        /// <value>
        /// <c>true</c> if the repository of this Logger has been configured.
        /// </value>
        /// <remarks>
        /// <para>
        /// Gets the flag that indicates if this repository has been configured.
        /// </para>
        /// </remarks>
        public bool Configured
        {
        get

        { return Hierarchy.Configured; }

        }

        Show
        Dominik Psenner added a comment - Oh, I just noticed that there is a "Configured" property in Hierarchy that could be wrapped in Logger like this: /// <summary> /// Gets the flag that indicates if the repository of this Logger has been configured. /// </summary> /// <value> /// <c>true</c> if the repository of this Logger has been configured. /// </value> /// <remarks> /// <para> /// Gets the flag that indicates if this repository has been configured. /// </para> /// </remarks> public bool Configured { get { return Hierarchy.Configured; } }
        Hide
        Dominik Psenner added a comment -

        Commited the Configured property as revision: 1489736

        Show
        Dominik Psenner added a comment - Commited the Configured property as revision: 1489736
        Hide
        Ron Grabowski added a comment - - edited

        ILog is the main interface for generating log messages. Shouldn't it stay focused on being an infrequently changing interface that is the entry point for sending messages into the system? As you pointed out the repository already knows if its configured:

        LogManager.GetRepository().Configured

        What's the next step for the user when Configured==false? This is possible today...little bit yucky because ConfigurationMessages is ICollection:

        var configErrorMessages = LogManager.GetRepository().ConfigurationMessages.Cast<LogLog>()
        .Where(x => x.Prefix.Contains("ERROR"))
        .Select(x => x.Message);

        I think effort should be put into upgrading ConfigurationMessages from ICollection to something that is more friendly for when Configured==false.

        If your repository contains appenders that follow the pattern of extending AppenderSkeleton and using OnlyOnceErrorHandler you might be able to get away with this if you're wanting to monitor things like file system permission/locking issues:

        // untested
        foreach (var appender in LogManager.GetRepository().GetAppenders())
        {
        var skeleton = appender as AppenderSkeleton;
        if (skeleton != null)
        {
        var onlyOnce = skeleton.ErrorHandler as OnlyOnceErrorHandler;
        if (onlyOnce != null && onlyOnce.IsEnabled)
        {
        Console.WriteLine("

        {0}

        :

        {1}

        ", appender.Name, onlyOnce.ErrorMessage);
        }
        }
        }

        Show
        Ron Grabowski added a comment - - edited ILog is the main interface for generating log messages. Shouldn't it stay focused on being an infrequently changing interface that is the entry point for sending messages into the system? As you pointed out the repository already knows if its configured: LogManager.GetRepository().Configured What's the next step for the user when Configured==false? This is possible today...little bit yucky because ConfigurationMessages is ICollection: var configErrorMessages = LogManager.GetRepository().ConfigurationMessages.Cast<LogLog>() .Where(x => x.Prefix.Contains("ERROR")) .Select(x => x.Message); I think effort should be put into upgrading ConfigurationMessages from ICollection to something that is more friendly for when Configured==false. If your repository contains appenders that follow the pattern of extending AppenderSkeleton and using OnlyOnceErrorHandler you might be able to get away with this if you're wanting to monitor things like file system permission/locking issues: // untested foreach (var appender in LogManager.GetRepository().GetAppenders()) { var skeleton = appender as AppenderSkeleton; if (skeleton != null) { var onlyOnce = skeleton.ErrorHandler as OnlyOnceErrorHandler; if (onlyOnce != null && onlyOnce.IsEnabled) { Console.WriteLine(" {0} : {1} ", appender.Name, onlyOnce.ErrorMessage); } } }
        Hide
        Dominik Psenner added a comment - - edited

        Yes it should stay focused on being the interface to log messages, but there's already the IsEnabled stuff (which by the way I would rather deprecate and do it implicitly) and therefore people expect a IsConfigured. LogManager.GetRepository().Configured is easy enough for someone who knows it, but hard to find and since people are lazy, they look at the ILog instance and subsequently ask silly questions. I agree that there's still work to be done on the ConfigurationMessages, but that's should probably be coped with a separate issue.

        Show
        Dominik Psenner added a comment - - edited Yes it should stay focused on being the interface to log messages, but there's already the IsEnabled stuff (which by the way I would rather deprecate and do it implicitly) and therefore people expect a IsConfigured. LogManager.GetRepository().Configured is easy enough for someone who knows it, but hard to find and since people are lazy, they look at the ILog instance and subsequently ask silly questions. I agree that there's still work to be done on the ConfigurationMessages, but that's should probably be coped with a separate issue.
        Hide
        Ron Grabowski added a comment -

        The IsEnabled's come in handy when you want check at a higher level if particular logger/level pair is enabled. Sometimes code takes a very different logic path when trace is enabled. That determination is made separately from the actual tracing.

        Do you expect log.IsConfigured to be called a lot outside of an application's startup code? I have a feeling most applications will call it just once. I'd hate to clutter up the main interface with a member that gets called infrequently and will always have the same value across all ILogs. LogManager.GetRepository().Configured still seems good enough. As far as discoverability goes, I fired up VS and found the property by navigating through a few small intellisense lists:

        log.Logger.Repository.Configured

        Let's assume log.IsConfigured==false, now where do I go? At some point they're going to have to deal with the repository to figure out what the problem is. I say we keep them close to the repository since that's what they're ultimately configuring and that's what they'll need to inspect before using ILog instances.

        Show
        Ron Grabowski added a comment - The IsEnabled's come in handy when you want check at a higher level if particular logger/level pair is enabled. Sometimes code takes a very different logic path when trace is enabled. That determination is made separately from the actual tracing. Do you expect log.IsConfigured to be called a lot outside of an application's startup code? I have a feeling most applications will call it just once. I'd hate to clutter up the main interface with a member that gets called infrequently and will always have the same value across all ILogs. LogManager.GetRepository().Configured still seems good enough. As far as discoverability goes, I fired up VS and found the property by navigating through a few small intellisense lists: log.Logger.Repository.Configured Let's assume log.IsConfigured==false, now where do I go? At some point they're going to have to deal with the repository to figure out what the problem is. I say we keep them close to the repository since that's what they're ultimately configuring and that's what they'll need to inspect before using ILog instances.
        Hide
        Dominik Psenner added a comment -

        Then someone should backout the commit and add a section to the FAQ or some other place where it makes sense.

        Show
        Dominik Psenner added a comment - Then someone should backout the commit and add a section to the FAQ or some other place where it makes sense.
        Hide
        Dominik Psenner added a comment - - edited

        I reverted my changes from revision 1489736 with revision: 1491695

        Show
        Dominik Psenner added a comment - - edited I reverted my changes from revision 1489736 with revision: 1491695
        Hide
        Dominik Psenner added a comment -

        Fixed with a FAQ entry as of revision: 1511226

        Show
        Dominik Psenner added a comment - Fixed with a FAQ entry as of revision: 1511226

          People

          • Assignee:
            Dominik Psenner
            Reporter:
            Joachim Zobel
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development