Quartz.Net, logging with Log4Net and Common.Logging throws "unknown log level"

Question

I have an Azure cloud service which uses Quartz.Net (2.3.2) to run scheduled tasks. My main logging engine is Log4Net (2.0.3) , and I am using Common.Logging.Log4Net1213 (3.0.0) to bridge Common.Logging and Log4Net. I am using my own "NinjectJobFactory" to create all the jobs and their dependencies (It implements IJobFactory). My schedule startup code looks like this:

  _scheduler = factory.GetScheduler();
  _scheduler.JobFactory = new NinjectJobFactory(_kernel);
  _scheduler.Start();

Everything works perfectly for normal, everyday logging (Quartz startup and shutdown, NServiceBus startup, tasks starting, exception handling inside jobs, etc). The problem I have is when there is a fatal exception in any of the lines above which prevents Quartz from starting. (Usually, this is because I have failed to properly include or configure a dependency that one of the jobs needs). Under these circumstances, instead of logging the real problem, I get an exception inside Log4NetLogger.cs complaining about an unknown logging level, and the underlying exception is never surfaced or logged. I have to break on caught exceptions in order to see the underlying exception. Can anyone suggest a fix? Thanks in advance!

The stack trace looks like this:

Microsoft.WindowsAzure.ServiceRuntime Critical: 1 : Unhandled Exception: System.ArgumentOutOfRangeException: unknown log level Parameter name: logLevel Actual value was Error. at Common.Logging.Log4Net.Log4NetLogger.GetLevel(LogLevel logLevel) in c:_oss\common-logging\src\Common.Logging.Log4Net129\Logging\Log4Net\Log4NetLogger.cs:line 180 at Common.Logging.Log4Net.Log4NetLogger.WriteInternal(LogLevel logLevel, Object message, Exception exception) in c:_oss\common-logging\src\Common.Logging.Log4Net129\Logging\Log4Net\Log4NetLogger.cs:line 140 at Common.Logging.Factory.AbstractLogger.Error(Object message, Exception exception) in c:_oss\common-logging\src\Common.Logging.Portable\Logging\Factory\AbstractLogger.cs:line 806 at Quartz.Simpl.SimpleThreadPool.WorkerThread.Run() in c:\Program Files (x86)\Jenkins\workspace\Quartz.NET\src\Quartz\Simpl\SimpleThreadPool.cs:line 492 at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state) at System.Threading.ThreadHelper.ThreadStart()

My common.logging config in the app.config is:

<common>
    <logging>
      <factoryAdapter type="Common.Logging.Log4Net.Log4NetLoggerFactoryAdapter, Common.Logging.Log4Net1213">
        <arg key="configType" value="FILE" />
        <arg key="configFile" value="log4net.config" />
      </factoryAdapter>
    </logging>
  </common>

Finally, my log4net.config is:

<log4net>
  <appender name="ErrorAppender" type="log4net.Appender.BufferingForwardingAppender">
    <bufferSize value="1" />
    <lossy value="true" />
    <evaluator type="log4net.Core.LevelEvaluator">
      <threshold value="INFO" />
    </evaluator>
    <appender-ref ref="TraceAppender" />
  </appender>
  <appender name="TraceAppender" type="log4net.Appender.TraceAppender">
    <threshold value="INFO" />
    <filter type="log4net.Filter.LoggerMatchFilter">
      <loggerToMatch value="NServiceBus.Azure.Transports.WindowsAzureServiceBus.AzureServiceBusQueueCreator" />
      <acceptOnMatch value="false" />
    </filter>
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%message%newline" />
    </layout>
  </appender>
  <root>
    <level value="ALL" />
    <appender-ref ref="ErrorAppender" />
  </root>
</log4net>

Answer 1

This may sound silly, but I was facing the exact same problem and I overcame it by making sure the versions of common.logging, common.logging.core, and common.logging.log4net1213 were all of the same version (3.3.1). Apparently, there is version dependency between the three libraries, and if one is used with another not the same version, this can result.

Here is the decompiled code for the function from which your exception is originating. It comes from Common.Logging.Log4Net1213 v3.3.1. Previous versions of this code didn't exactly account for Common.Logging.LogLevel.Warn, and so the exception fell out at the bottom of the switch statement:

 public static Level GetLevel(Common.Logging.LogLevel logLevel)
    {
      switch (logLevel)
      {
        case Common.Logging.LogLevel.All:
          return Level.All;
        case Common.Logging.LogLevel.Trace:
          return Level.Trace;
        case Common.Logging.LogLevel.Debug:
          return Level.Debug;
        case Common.Logging.LogLevel.Info:
          return Level.Info;
        case Common.Logging.LogLevel.Warn:
          return Level.Warn;
        case Common.Logging.LogLevel.Error:
          return Level.Error;
        case Common.Logging.LogLevel.Fatal:
          return Level.Fatal;
        default:
          throw new ArgumentOutOfRangeException("logLevel", (object) logLevel, "unknown log level");
      }
    }

In my case, common.logging.log4net1213 was one version behind the others (v3.3.0), so I updated the library to the same version as the other two libraries, and the problem evaporated.

Good luck!

Answer 2

Can you show us your log config?

My Servicebus/log4net/quartz implementation logs quartz startup issues successfully. This is the startup code i use; not sure if it will help as not seen your code.

NSB Version 4.6.2

public class MyServer : ServiceControl
{
    private readonly ILog logger;
    private ISchedulerFactory schedulerFactory;
    private IScheduler scheduler;

    public static IBus Bus = null;

    public MyServer()
    {
        logger = LogManager.GetLogger(GetType());                       
    }


    public virtual void Initialize()
    {
        try
        {                           
            log4net.GlobalContext.Properties["Job"] = "Quartz";

            Configure.Serialization.Xml();
            Configure.Transactions.Enable();
            SetLoggingLibrary.Log4Net();

            Bus = Configure.With().DefaultBuilder().UnicastBus().SendOnly();

            schedulerFactory = CreateSchedulerFactory();
            scheduler = GetScheduler();
        }
        catch (Exception e)
        {
            logger.Error("Server initialization failed:" + e.Message, e);
            throw;
        }
    } 
}

public class Configuration
{
    private static readonly NameValueCollection configuration;

    static Configuration()
    {
        configuration = (NameValueCollection)ConfigurationManager.GetSection("quartz");
    }


    static public string GetQuartzConfigFileName()
    {
        return configuration["quartz.plugin.xml.fileNames"] as String;
    }
}

And my app config looks like this

<configuration>
  <configSections>
    <section name="quartz" type="System.Configuration.NameValueSectionHandler, System, Version=1.0.5000.0,Culture=neutral, PublicKeyToken=b77a5c561934e089" />
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net" />
    <sectionGroup name="common">
      <section name="logging" type="Common.Logging.ConfigurationSectionHandler, Common.Logging" />
    </sectionGroup>
    </configSections>
  <common>
   <logging>
      <factoryAdapter type="Common.Logging.Log4Net.Log4NetLoggerFactoryAdapter, Common.Logging.Log4net1211">
        <arg key="configType" value="INLINE" />
      </factoryAdapter>
    </logging>
  </common>
  <log4net debug="false">
    <appender name="ColoredConsoleAppender" type="log4net.Appender.ColoredConsoleAppender">
      <mapping>
        <level value="FATAL" />
        <foreColor value="Red, HighIntensity" />
      </mapping>
      <mapping>
        <level value="ERROR" />
        <foreColor value="Red, HighIntensity" />
      </mapping>
      <mapping>
        <level value="WARN" />
        <foreColor value="Yellow" />
      </mapping>
      <mapping>
        <level value="INFO" />
        <foreColor value="Green" />
      </mapping>
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline" />
      </layout>
    </appender>

    <appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
      <file value="GrafOI.Scheduler.log" />
      <appendToFile value="true" />
      <rollingStyle value="Size" />
      <maxSizeRollBackups value="10" />
      <maximumFileSize value="10000KB" />
      <staticLogFileName value="true" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline" />
      </layout>
    </appender>

    <!-- quartz clutters the logs so turn it off unless an error occurs -->
    <logger name="Quartz">
      <level value="ERROR" />
    </logger>

    <root>
      <level value="DEBUG" />
      <appender-ref ref="AdoNetAppender" />
      <appender-ref ref="EventLogAppender" />
      <appender-ref ref="ColoredConsoleAppender" />
      <appender-ref ref="RollingFileAppender" />
    </root>
  </log4net>
  <quartz>
    <add key="quartz.scheduler.instanceName" value="GrafOI Scheduler" />
    <add key="quartz.threadPool.type" value="Quartz.Simpl.SimpleThreadPool, Quartz" />
    <add key="quartz.threadPool.threadCount" value="2" />
    <add key="quartz.threadPool.threadPriority" value="Normal" />
    <add key="quartz.jobStore.misfireThreshold" value="60000" />
    <add key="quartz.jobStore.type" value="Quartz.Impl.AdoJobStore.JobStoreTX, Quartz" />
    <add key="quartz.jobStore.driverDelegateType" value="Quartz.Impl.AdoJobStore.StdAdoDelegate, Quartz" />
    <add key="quartz.jobStore.tablePrefix" value="QRTZ_" />
    <add key="quartz.jobStore.dataSource" value="myDS" />
    <add key="quartz.dataSource.myDS.connectionString" value="server=.;database=GrafOI;Integrated Security=true;" />
    <add key="quartz.dataSource.myDS.provider" value="SqlServer-20" />
    <add key="quartz.plugin.xml.type" value="Quartz.Plugin.Xml.XMLSchedulingDataProcessorPlugin, Quartz" />
    <add key="quartz.plugin.xml.fileNames" value="~/GrafOI.Scheduler.Jobs.xml" />
    <add key="quartz.jobStore.useProperties" value="true" />

  </quartz>
  <appSettings>

  </appSettings>

</configuration>

Maybe there is something in there that helps