Uploaded image for project: 'Log4net'
  1. Log4net
  2. LOG4NET-551

LockRecursionException when using File Appenders

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Minor
    • Resolution: Fixed
    • Affects Version/s: 2.0.7
    • Fix Version/s: 2.0.8
    • Component/s: None
    • Labels:
      None

      Description

      I have been getting the following exception on the console:

      log4net:ERROR Exception while logging
      System.Threading.LockRecursionException: Recursive read lock acquisitions not allowed in this mode.
      at System.Threading.ReaderWriterLockSlim.TryEnterReadLockCore(TimeoutTracker timeout)
      at System.Threading.ReaderWriterLockSlim.TryEnterReadLock(TimeoutTracker timeout)
      at System.Threading.ReaderWriterLockSlim.EnterReadLock()
      at log4net.Util.ReaderWriterLock.AcquireReaderLock()
      at log4net.Repository.Hierarchy.Logger.CallAppenders(LoggingEvent loggingEvent)
      at log4net.Repository.Hierarchy.Logger.ForcedLog(Type callerStackBoundaryDeclaringType, Level level, Object message, Exception exception)
      at log4net.Repository.Hierarchy.Logger.Log(Type callerStackBoundaryDeclaringType, Level level, Object message, Exception exception)

      I have a number of different appenders, but this only happens when I am using `log4net.Appender.FileAppender`.

      Using a debugger, I was able to narrow it down to this line (I replaced curly brackets with square brackets because otherwise JIRA interprets them as macros):

      Logger.DebugFormat("[1] Executing SQL: [0][2][0]With parameters: [3]",
      Environment.NewLine, methodName, sql, new ToStringWrapper(parameters));

      My first thought was that ToStringWrapper() was throwing an exception or generating another logging call. But If I put breakpoints at the log call and at the first line of ToStringWrapper.ToString, the exception will show up in the console between those two points.

      Oddly enough, if I "step into" the logging call instead of just "continuing" and letting the breakpoints handle it, no exception happens.

        Issue Links

          Activity

          Hide
          dklausner75@gmail.com Dan K added a comment - - edited

          Awesome news!!! Thank you guys so much! I will go add it today via NuGet package and provide feedback!

          Show
          dklausner75@gmail.com Dan K added a comment - - edited Awesome news!!! Thank you guys so much! I will go add it today via NuGet package and provide feedback!
          Hide
          bodewig Stefan Bodewig added a comment -

          Last Saturday

          Sorry, I thought you'd be subscribed to one of our lists and had seen the announcement. 2.0.8 is already there.

          Show
          bodewig Stefan Bodewig added a comment - Last Saturday Sorry, I thought you'd be subscribed to one of our lists and had seen the announcement. 2.0.8 is already there.
          Hide
          dklausner75@gmail.com Dan K added a comment - - edited

          Hi Stefan,

          I see the voting process is complete and positive news! Do you have a timetable as to when this release (v2.0.8) will be cut/available in NuGet?

          Thanks,

          Danny

          Show
          dklausner75@gmail.com Dan K added a comment - - edited Hi Stefan, I see the voting process is complete and positive news! Do you have a timetable as to when this release (v2.0.8) will be cut/available in NuGet? Thanks, Danny
          Show
          bodewig Stefan Bodewig added a comment - vote mail with links to the artifacts that may become 2.0.8: https://lists.apache.org/thread.html/0ac8cdaf4a2fc6d261cf1b1f878ced5dcff7f7df612042d6efb6a6c6@%3Clog4net-dev.logging.apache.org%3E
          Hide
          dklausner75@gmail.com Dan K added a comment -

          Hi Stefan,

          This is awesome news and thank you/your team for staying on top of this effort! You have our vote! Also, we now have 3 different test systems with v2.0.8 (locally built version) still running full throttle and no exceptions. This is the results we we were looking for and hopefully our findings can help others as well. We will be glad to test the "official" release v2.0.8 when it comes out. I will post feedback/results after that's done. Thanks again!

          Show
          dklausner75@gmail.com Dan K added a comment - Hi Stefan, This is awesome news and thank you/your team for staying on top of this effort! You have our vote! Also, we now have 3 different test systems with v2.0.8 (locally built version) still running full throttle and no exceptions. This is the results we we were looking for and hopefully our findings can help others as well. We will be glad to test the "official" release v2.0.8 when it comes out. I will post feedback/results after that's done. Thanks again!
          Hide
          bodewig Stefan Bodewig added a comment -

          I'll be cutting a release candidate this week and then we'll vote on it, which will at least take three days. Chances are 2.0.8 will get released sometime during the next week.

          Once the release candidate is ready I'll leave a note here, maybe you can give it a try as well.

          Show
          bodewig Stefan Bodewig added a comment - I'll be cutting a release candidate this week and then we'll vote on it, which will at least take three days. Chances are 2.0.8 will get released sometime during the next week. Once the release candidate is ready I'll leave a note here, maybe you can give it a try as well.
          Hide
          dklausner75@gmail.com Dan K added a comment - - edited

          Hi Stefan,

          Update:

          1) I cloned and built v2.0.8 from latest trunk to upgrade as you suggested.
          In our case, this is will be for testing purposes only until we get an
          official release through NuGet.

          2) Running a new build of our own software using v2.0.8 since yesterday
          morning and no more "LockRecursionExceptions". We usually see these
          immediately with v2.0.7, but wanted to run all day/overnight under heavy
          load just to make our case.

          Please let me know if there is anything else you would like us to try to
          help expedite official release of v2.0.8. We understand/respect this is
          open source and the process for releases is different, but your help to
          make this happen is very much appreciated. I am sure others will appreciate
          this release too as they learn their version could be "silently" throwing this
          particular exception since version 1.2.12.

          On Mar 6, 2017 6:11 AM, "Stefan Bodewig (JIRA)" <jira@apache.org> wrote:

          [ https://issues.apache.org/jira/browse/LOG4NET-551?page=com.
          atlassian.jira.plugin.system.issuetabpanels:comment-tabpane
          l&focusedCommentId=15897107#comment-15897107 ]

          Stefan Bodewig commented on LOG4NET-551:
          ----------------------------------------

          anything that ensures the release will actually fix the problem for you
          will be good.

          This issue must have been present since 1.2.12.

          not allowed in this mode.
          timeout)
          timeout)
          loggingEvent)
          callerStackBoundaryDeclaringType, Level level, Object message, Exception
          exception)
          callerStackBoundaryDeclaringType, Level level, Object message, Exception
          exception)
          using `log4net.Appender.FileAppender`.
          curly brackets with square brackets because otherwise JIRA interprets them
          as macros):
          ToStringWrapper(parameters));
          generating another logging call. But If I put breakpoints at the log call
          and at the first line of ToStringWrapper.ToString, the exception will show
          up in the console between those two points.
          "continuing" and letting the breakpoints handle it, no exception happens.


          This message was sent by Atlassian JIRA
          (v6.3.15#6346)

          Show
          dklausner75@gmail.com Dan K added a comment - - edited Hi Stefan, Update: 1) I cloned and built v2.0.8 from latest trunk to upgrade as you suggested. In our case, this is will be for testing purposes only until we get an official release through NuGet. 2) Running a new build of our own software using v2.0.8 since yesterday morning and no more "LockRecursionExceptions". We usually see these immediately with v2.0.7, but wanted to run all day/overnight under heavy load just to make our case. Please let me know if there is anything else you would like us to try to help expedite official release of v2.0.8. We understand/respect this is open source and the process for releases is different, but your help to make this happen is very much appreciated. I am sure others will appreciate this release too as they learn their version could be "silently" throwing this particular exception since version 1.2.12. On Mar 6, 2017 6:11 AM, "Stefan Bodewig (JIRA)" <jira@apache.org> wrote: [ https://issues.apache.org/jira/browse/LOG4NET-551?page=com . atlassian.jira.plugin.system.issuetabpanels:comment-tabpane l&focusedCommentId=15897107#comment-15897107 ] Stefan Bodewig commented on LOG4NET-551 : ---------------------------------------- anything that ensures the release will actually fix the problem for you will be good. This issue must have been present since 1.2.12. not allowed in this mode. timeout) timeout) loggingEvent) callerStackBoundaryDeclaringType, Level level, Object message, Exception exception) callerStackBoundaryDeclaringType, Level level, Object message, Exception exception) using `log4net.Appender.FileAppender`. curly brackets with square brackets because otherwise JIRA interprets them as macros): ToStringWrapper(parameters)); generating another logging call. But If I put breakpoints at the log call and at the first line of ToStringWrapper.ToString, the exception will show up in the console between those two points. "continuing" and letting the breakpoints handle it, no exception happens. – This message was sent by Atlassian JIRA (v6.3.15#6346)
          Hide
          dklausner75@gmail.com Dan K added a comment - - edited

          Hi Stefan, here is more context around our experience with v2.0.7:

          1) During latest development cycle, we upgraded straight from version 1.2.11 to v2.0.6, then the same week to v2.0.7 with intent to use for upcoming release.

          2) We haven't seen this exception until the upgrade to v2.0.7 and wouldn't have known about this error prior since it wasn't present in 1.2.11, which is consistent with your last comment.

          3: This is the exception we see with log4net internal debugging on using v2.0.7:

          log4net:ERROR Exception while logging
          System.Threading.LockRecursionException: Recursive read lock acquisitions not allowed in this mode.
          at System.Threading.ReaderWriterLockSlim.TryEnterReadLockCore(TimeoutTracker timeout)
          at System.Threading.ReaderWriterLockSlim.TryEnterReadLock(TimeoutTracker timeout)
          at log4net.Util.ReaderWriterLock.AcquireReaderLock()
          at log4net.Repository.Hierarchy.Logger.CallAppenders(LoggingEvent loggingEvent)
          at log4net.Repository.Hierarchy.Logger.ForcedLog(Type callerStackBoundaryDeclaringType, Level level, Object message, Exception exception)
          at log4net.Repository.Hierarchy.Logger.Log(Type callerStackBoundaryDeclaringType, Level level, Object message, Exception exception)

          Show
          dklausner75@gmail.com Dan K added a comment - - edited Hi Stefan, here is more context around our experience with v2.0.7: 1) During latest development cycle, we upgraded straight from version 1.2.11 to v2.0.6, then the same week to v2.0.7 with intent to use for upcoming release. 2) We haven't seen this exception until the upgrade to v2.0.7 and wouldn't have known about this error prior since it wasn't present in 1.2.11, which is consistent with your last comment. 3: This is the exception we see with log4net internal debugging on using v2.0.7: log4net:ERROR Exception while logging System.Threading.LockRecursionException: Recursive read lock acquisitions not allowed in this mode. at System.Threading.ReaderWriterLockSlim.TryEnterReadLockCore(TimeoutTracker timeout) at System.Threading.ReaderWriterLockSlim.TryEnterReadLock(TimeoutTracker timeout) at log4net.Util.ReaderWriterLock.AcquireReaderLock() at log4net.Repository.Hierarchy.Logger.CallAppenders(LoggingEvent loggingEvent) at log4net.Repository.Hierarchy.Logger.ForcedLog(Type callerStackBoundaryDeclaringType, Level level, Object message, Exception exception) at log4net.Repository.Hierarchy.Logger.Log(Type callerStackBoundaryDeclaringType, Level level, Object message, Exception exception)
          Hide
          bodewig Stefan Bodewig added a comment -

          anything that ensures the release will actually fix the problem for you will be good.

          This issue must have been present since 1.2.12.

          Show
          bodewig Stefan Bodewig added a comment - anything that ensures the release will actually fix the problem for you will be good. This issue must have been present since 1.2.12.
          Hide
          dklausner75@gmail.com Dan K added a comment - - edited

          Upgrading should be a good thing, which is why we didn't mind going to v2.0.7 initially. Log4net is our go-to for both file logging/db logging and as part of testing procedure after upgrade, report any "silent" exceptions/degrades. As a result, we started seeing this exception consistently and noticed it's isolated when file appender is used. We notice a huge difference between messages written to DB (more) vs to file because of these exceptions and file logging losing messages. Others probably haven't reported it because they aren't enabling internal debugging/trace listeners or don't have DB/File logging capabilities to compare that something is wrong. I will post the exception we see as well here to further uphold our findings and perhaps help others that experience same thing. I can build the dependency from trunk just to verify the fix addresses it, but we see that when the appender is called that it can't recursively log when using the default policy in .net 4.0/above, which the fix in v2.0.8 addresses.

          Show
          dklausner75@gmail.com Dan K added a comment - - edited Upgrading should be a good thing, which is why we didn't mind going to v2.0.7 initially. Log4net is our go-to for both file logging/db logging and as part of testing procedure after upgrade, report any "silent" exceptions/degrades. As a result, we started seeing this exception consistently and noticed it's isolated when file appender is used. We notice a huge difference between messages written to DB (more) vs to file because of these exceptions and file logging losing messages. Others probably haven't reported it because they aren't enabling internal debugging/trace listeners or don't have DB/File logging capabilities to compare that something is wrong. I will post the exception we see as well here to further uphold our findings and perhaps help others that experience same thing. I can build the dependency from trunk just to verify the fix addresses it, but we see that when the appender is called that it can't recursively log when using the default policy in .net 4.0/above, which the fix in v2.0.8 addresses.
          Hide
          bodewig Stefan Bodewig added a comment -

          The limiting factor is time available to those who do the work of cutting and vetting a release. We are all volunteers here in the case of 2.0.7 it just happened to be the case that I had time at hand (vacation).

          OTOH I've not considered this problem to be wide-spread given it must have happened ever since log4net started using ReaderWriterLockSlim and it looked as if it had never been reported before. LOG4NET-466 might be an earlier report but unfortunately the reporter never responded when asked whether the problem was fixed with 1.2.14 - and so I assumed it was a duplicate of LOG4NET-443.

          I'll try to carve out some time for cutting a release, but if your release date depends on us, then you should seriously consider building log4net from sources yourself. At the very least you should build it from source in order to verify the fix actually fixes your problem - and we are not looking at a different cause of a problem that happens to show up with the same symptoms.

          Show
          bodewig Stefan Bodewig added a comment - The limiting factor is time available to those who do the work of cutting and vetting a release. We are all volunteers here in the case of 2.0.7 it just happened to be the case that I had time at hand (vacation). OTOH I've not considered this problem to be wide-spread given it must have happened ever since log4net started using ReaderWriterLockSlim and it looked as if it had never been reported before. LOG4NET-466 might be an earlier report but unfortunately the reporter never responded when asked whether the problem was fixed with 1.2.14 - and so I assumed it was a duplicate of LOG4NET-443 . I'll try to carve out some time for cutting a release, but if your release date depends on us, then you should seriously consider building log4net from sources yourself. At the very least you should build it from source in order to verify the fix actually fixes your problem - and we are not looking at a different cause of a problem that happens to show up with the same symptoms.
          Hide
          dklausner75@gmail.com Dan K added a comment - - edited

          Stefan, that doesn't seem very reasonable. Especially, given any time this particular exception occurs, log event/messages are completely lost. That is completely unacceptable in a production setting. I would think at the very least, now that this issue has been made aware of, some sort of hot fix/patch for v2.0.7 become "officially" available if v2.0.8 has to wait. If I recall correctly, one minor bug found in v2.0.6 triggered an immediate fix/release through NuGet and made available that same week (v2.0.7). Why would this be handled any different? Again, the alternative methods mentioned in this thread aren't a viable option.

          Show
          dklausner75@gmail.com Dan K added a comment - - edited Stefan, that doesn't seem very reasonable. Especially, given any time this particular exception occurs, log event/messages are completely lost. That is completely unacceptable in a production setting. I would think at the very least, now that this issue has been made aware of, some sort of hot fix/patch for v2.0.7 become "officially" available if v2.0.8 has to wait. If I recall correctly, one minor bug found in v2.0.6 triggered an immediate fix/release through NuGet and made available that same week (v2.0.7). Why would this be handled any different? Again, the alternative methods mentioned in this thread aren't a viable option.
          Hide
          bodewig Stefan Bodewig added a comment -

          I'm sorry to say that we haven't even talked about cutting a new release, yet. So it will be a while until 2.0.8 gets released.

          Show
          bodewig Stefan Bodewig added a comment - I'm sorry to say that we haven't even talked about cutting a new release, yet. So it will be a while until 2.0.8 gets released.
          Hide
          dklausner75@gmail.com Dan K added a comment - - edited

          Hi Stefan, thank you for the fast response and invaluable information. When is v2.0.8 expected to be released? Building it ourselves isn't a preferred option to upgrade. We have an upcoming release and rely on NuGet for packages for upgrades. Also, reverting to log4net v2.0.7 to use .Net Framework 3.5 isn't an option. We would love to take advantage of "all" the fixes/improvements in v2.0.8. Thanks again!

          Show
          dklausner75@gmail.com Dan K added a comment - - edited Hi Stefan, thank you for the fast response and invaluable information. When is v2.0.8 expected to be released? Building it ourselves isn't a preferred option to upgrade. We have an upcoming release and rely on NuGet for packages for upgrades. Also, reverting to log4net v2.0.7 to use .Net Framework 3.5 isn't an option. We would love to take advantage of "all" the fixes/improvements in v2.0.8. Thanks again!
          Hide
          bodewig Stefan Bodewig added a comment -

          The fix applies to all versions that have ReaderWriterLockSlim (those without it haven't been affected anyway. So yes, it should also apply to 4.5 and 4.6.

          On the other 2.0.8 hasn't been released, yet. In order to upgrade to it, you'd have to build log4net yourself from the current tip of the svn trunk (or the trunk branch of the github mirror).

          Show
          bodewig Stefan Bodewig added a comment - The fix applies to all versions that have ReaderWriterLockSlim (those without it haven't been affected anyway. So yes, it should also apply to 4.5 and 4.6. On the other 2.0.8 hasn't been released, yet. In order to upgrade to it, you'd have to build log4net yourself from the current tip of the svn trunk (or the trunk branch of the github mirror).
          Hide
          dklausner75@gmail.com Dan K added a comment - - edited

          Hi, we recently updated to Log4net version 2.0.7 and also experiencing the "LockRecursionException". I see the above PR (https://issues.apache.org/jira/browse/LOG4NET-550) covers .Net Framework 4.0, but does it also support .Net 4.5/above? I confirmed the log4net version (2.0.7) we are using is against .Net 4.5 when we see the errors. Your feedback/help is much appreciated before we upgrade to 2.0.8! Thanks!

          Show
          dklausner75@gmail.com Dan K added a comment - - edited Hi, we recently updated to Log4net version 2.0.7 and also experiencing the "LockRecursionException". I see the above PR ( https://issues.apache.org/jira/browse/LOG4NET-550 ) covers .Net Framework 4.0, but does it also support .Net 4.5/above? I confirmed the log4net version (2.0.7) we are using is against .Net 4.5 when we see the errors. Your feedback/help is much appreciated before we upgrade to 2.0.8! Thanks!
          Hide
          mclefoster Matthew Lefoster added a comment -

          Joe, You were ultimately right. I went down the call stack and found a logging call in at least one of the instances where the warning showed up. (A class we had to redact the log had to check the configuration settings for redaction parameters, and checking the configuration framework caused logging calls...) It's still odd to me that the behavior changed depending on how exactly I stepped through with the debugger, but it's irrelevant now, because that PR made the issue disappear!

          Thank you very much for your help. Since this'll be fixed presumably in the next version, I'll go ahead and mark this issue resolved.

          Show
          mclefoster Matthew Lefoster added a comment - Joe, You were ultimately right. I went down the call stack and found a logging call in at least one of the instances where the warning showed up. (A class we had to redact the log had to check the configuration settings for redaction parameters, and checking the configuration framework caused logging calls...) It's still odd to me that the behavior changed depending on how exactly I stepped through with the debugger, but it's irrelevant now, because that PR made the issue disappear! Thank you very much for your help. Since this'll be fixed presumably in the next version, I'll go ahead and mark this issue resolved.
          Hide
          mclefoster Matthew Lefoster added a comment -

          I'll take it for a spin today, thank you!

          Show
          mclefoster Matthew Lefoster added a comment - I'll take it for a spin today, thank you!
          Hide
          bodewig Stefan Bodewig added a comment -

          Our comments collided in flight even if the timestamps say I could have read yours, JocularJoe

          It's not obvious to me how SystemStringFormat might cause new log messages to enter the logging system unless LogLog had subscribers sending stuff back to log4net but I trust you this is the case.

          I've just merged your PR and will close LOG4NET-550.

          Matthew Lefoster could you build log4net from trunk and see whether this fixes the problem for you?

          Show
          bodewig Stefan Bodewig added a comment - Our comments collided in flight even if the timestamps say I could have read yours, JocularJoe It's not obvious to me how SystemStringFormat might cause new log messages to enter the logging system unless LogLog had subscribers sending stuff back to log4net but I trust you this is the case. I've just merged your PR and will close LOG4NET-550 . Matthew Lefoster could you build log4net from trunk and see whether this fixes the problem for you?
          Hide
          JoeJoe Joe added a comment -

          Stefan, when using DebugFormat, the message in the LoggingEvent will be a log4net.Util.SystemStringFormat containing the format string and arguments passed by the caller. ToString() will be called on the arguments when the appender formats the message, causing recursion.

          Show
          JoeJoe Joe added a comment - Stefan, when using DebugFormat, the message in the LoggingEvent will be a log4net.Util.SystemStringFormat containing the format string and arguments passed by the caller. ToString() will be called on the arguments when the appender formats the message, causing recursion.
          Hide
          bodewig Stefan Bodewig added a comment -

          Even though I don't really see how recursive calls between appenders may be happing here, it probably would get resolved by LOG4NET-550.

          Show
          bodewig Stefan Bodewig added a comment - Even though I don't really see how recursive calls between appenders may be happing here, it probably would get resolved by LOG4NET-550 .
          Hide
          JoeJoe Joe added a comment -

          This probably has the same root cause as LOG4NET-550.
          A workaround would be to use the .NET 3.5 DLL, which uses ReaderWriterLock rather than ReaderWriterLockSlim and doesn't have this problem.
          I suspect your ToStringWrapper.ToString() method is doing some logging, which is causing this attempt at recursion and perhaps isn't a good idea.

          Show
          JoeJoe Joe added a comment - This probably has the same root cause as LOG4NET-550 . A workaround would be to use the .NET 3.5 DLL, which uses ReaderWriterLock rather than ReaderWriterLockSlim and doesn't have this problem. I suspect your ToStringWrapper.ToString() method is doing some logging, which is causing this attempt at recursion and perhaps isn't a good idea.

            People

            • Assignee:
              Unassigned
              Reporter:
              mclefoster Matthew Lefoster
            • Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development