Details

    • Type: Bug
    • Status: Resolved
    • Priority: Critical
    • Resolution: Fixed
    • Affects Version/s: 1.2.13
    • Fix Version/s: 1.2.14, 1.3.0
    • Component/s: None
    • Labels:
      None
    • Environment:
      Windows service implemented with .NET 4.5 using Log4Net 1.2.13 on Windows 2008 R2

      Description

      I do have an .NET application (Windows Service) that collects data from a lot of sources (DBs, log files, machines event logs, ...) and uses Log4Net to log details of the actions / execution. As expected, I'm using a high number of threads to collect data, threads that are writing logs in some files (RollingFileAppenderer).

      Lately it happens that the entire application is BLOCKED because all threads were trying to acquire a read lock, like in the stack trace:
      000000001ac3d998 00000000774715fa [HelperMethodFrame: 000000001ac3d998] System.Threading.Thread.SleepInternal(Int32)
      000000001ac3da90 000007fef747b5e9 System.Threading.Thread.Sleep(Int32)
      000000001ac3dac0 000007fef5fb9631 System.Threading.ReaderWriterLockSlim.EnterMyLockSpin()
      000000001ac3db90 000007fef5cd297e System.Threading.ReaderWriterLockSlim.TryEnterReadLockCore(TimeoutTracker)
      000000001ac3dbf0 000007fef5cd28fa System.Threading.ReaderWriterLockSlim.TryEnterReadLock(TimeoutTracker)
      000000001ac3dc40 000007fe98fb4efd log4net.Repository.Hierarchy.Logger.CallAppenders(log4net.Core.LoggingEvent)
      000000001ac3dcc0 000007fe98fb4907 log4net.Repository.Hierarchy.Logger.Log(System.Type, log4net.Core.Level, System.Object, System.Exception)
      000000001ac3dd30 000007fe98fb47f9 log4net.Core.LogImpl.Info(System.Object)

      It's important to mention that my threads have a timeout, and if they do not finish the job in the given interval they are ABORTED.

      Searching for a solution, I found a possible explanation of application hanging here: http://chabster.blogspot.ro/2013/07/a-story-of-orphaned-readerwriterlockslim.html

      1. log4net.xml
        1 kB
        Calin Pavel

        Activity

        Hide
        calin.pavel Calin Pavel added a comment -

        For configuring log4net I'm using an XML (attached) and some dynamic configuration:
        private void addLogger(Hierarchy loggerRepository, MonitorConfig monitorConfig)
        {
        Logger root = loggerRepository.Root;
        RollingFileAppender mainAppender = (RollingFileAppender)root.GetAppender(MAIN_FILE_APPENDER_NAME);
        string logPath = mainAppender.File;
        string logDir = logPath.Substring(0, logPath.LastIndexOf(@"\"));

        // create the appender
        RollingFileAppender monitorAppender = new RollingFileAppender();
        monitorAppender.Name = buildAppendererName(monitorConfig);
        monitorAppender.File = Path.Combine(logDir, MONITOR_LOGGING_PARENT_DIR, monitorConfig.name) + @"\";

        // Copy values from the DataCollector appenderer (main appenderer)
        monitorAppender.DatePattern = DateHelper.DATE_FORMAT + "'_" + monitorConfig.name + ".log'";
        monitorAppender.AppendToFile = mainAppender.AppendToFile;
        monitorAppender.RollingStyle = mainAppender.RollingStyle;
        monitorAppender.StaticLogFileName = mainAppender.StaticLogFileName;
        monitorAppender.PreserveLogFileNameExtension = mainAppender.PreserveLogFileNameExtension;

        PatternLayout layout = new PatternLayout("%date [%thread] %-5level %logger

        {1}

        :%L - %message%newline");
        monitorAppender.Layout = layout;
        monitorAppender.Threshold = monitorConfig.loggingLevel;

        PropertyFilter filter = new PropertyFilter();
        filter.Key = LoggingConstants.THREAD_LOGGING_KEY;
        filter.StringToMatch = monitorConfig.name;

        DenyAllFilter filterDeny = new log4net.Filter.DenyAllFilter();

        monitorAppender.AddFilter(filter);
        monitorAppender.AddFilter(filterDeny);
        monitorAppender.ActivateOptions();

        // create the logger
        Logger rootLogger = (Logger)LogManager.GetLogger(ROOT_LEVEL).Logger;

        // Force DEBUG level for logger. Filter by level will be done by appenderer
        rootLogger.Level = Level.Debug;

        rootLogger.AddAppender(monitorAppender);
        }

        Show
        calin.pavel Calin Pavel added a comment - For configuring log4net I'm using an XML (attached) and some dynamic configuration: private void addLogger(Hierarchy loggerRepository, MonitorConfig monitorConfig) { Logger root = loggerRepository.Root; RollingFileAppender mainAppender = (RollingFileAppender)root.GetAppender(MAIN_FILE_APPENDER_NAME); string logPath = mainAppender.File; string logDir = logPath.Substring(0, logPath.LastIndexOf(@"\")); // create the appender RollingFileAppender monitorAppender = new RollingFileAppender(); monitorAppender.Name = buildAppendererName(monitorConfig); monitorAppender.File = Path.Combine(logDir, MONITOR_LOGGING_PARENT_DIR, monitorConfig.name) + @"\"; // Copy values from the DataCollector appenderer (main appenderer) monitorAppender.DatePattern = DateHelper.DATE_FORMAT + "'_" + monitorConfig.name + ".log'"; monitorAppender.AppendToFile = mainAppender.AppendToFile; monitorAppender.RollingStyle = mainAppender.RollingStyle; monitorAppender.StaticLogFileName = mainAppender.StaticLogFileName; monitorAppender.PreserveLogFileNameExtension = mainAppender.PreserveLogFileNameExtension; PatternLayout layout = new PatternLayout("%date [%thread] %-5level %logger {1} :%L - %message%newline"); monitorAppender.Layout = layout; monitorAppender.Threshold = monitorConfig.loggingLevel; PropertyFilter filter = new PropertyFilter(); filter.Key = LoggingConstants.THREAD_LOGGING_KEY; filter.StringToMatch = monitorConfig.name; DenyAllFilter filterDeny = new log4net.Filter.DenyAllFilter(); monitorAppender.AddFilter(filter); monitorAppender.AddFilter(filterDeny); monitorAppender.ActivateOptions(); // create the logger Logger rootLogger = (Logger)LogManager.GetLogger(ROOT_LEVEL).Logger; // Force DEBUG level for logger. Filter by level will be done by appenderer rootLogger.Level = Level.Debug; rootLogger.AddAppender(monitorAppender); }
        Hide
        nachbarslumpi Dominik Psenner added a comment -

        This could be indeed an orphaned lock issue if thread aborts happen regularily. Is your Win2008 server running on x64 or x32?

        Show
        nachbarslumpi Dominik Psenner added a comment - This could be indeed an orphaned lock issue if thread aborts happen regularily. Is your Win2008 server running on x64 or x32?
        Hide
        calin.pavel Calin Pavel added a comment -

        It's a Win 2008 R2 x64

        Show
        calin.pavel Calin Pavel added a comment - It's a Win 2008 R2 x64
        Hide
        nachbarslumpi Dominik Psenner added a comment -

        Then this one might be hitting you here:

        http://joeduffyblog.com/2007/01/29/monitorenter-thread-aborts-and-orphaned-locks/

        Quite worrying .. That blog post tells us this: THOU SHALL NOT ABORT THREADS. As far as I can understand this you will have to work around this issue by untangling the threads.

        Show
        nachbarslumpi Dominik Psenner added a comment - Then this one might be hitting you here: http://joeduffyblog.com/2007/01/29/monitorenter-thread-aborts-and-orphaned-locks/ Quite worrying .. That blog post tells us this: THOU SHALL NOT ABORT THREADS. As far as I can understand this you will have to work around this issue by untangling the threads.
        Hide
        nachbarslumpi Dominik Psenner added a comment -

        Or maybe you could try to use several remoting appenders that send events to one remoting sink which then writes to the log files? This could be a safe way to abort threads without leaking locks since every thread has his own appender and does not have to be synchronized with the other threads.

        Show
        nachbarslumpi Dominik Psenner added a comment - Or maybe you could try to use several remoting appenders that send events to one remoting sink which then writes to the log files? This could be a safe way to abort threads without leaking locks since every thread has his own appender and does not have to be synchronized with the other threads.
        Hide
        bodewig Stefan Bodewig added a comment -

        implemented the try/finally workaround mentioned in Andrii Chabykins post with svn revision 1670018

        Show
        bodewig Stefan Bodewig added a comment - implemented the try/finally workaround mentioned in Andrii Chabykins post with svn revision 1670018

          People

          • Assignee:
            Unassigned
            Reporter:
            calin.pavel Calin Pavel
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development