Log4net
  1. Log4net
  2. LOG4NET-178

Log4Net stops logging after appdomain recycle of ASP.NET2.0 application

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Invalid
    • Affects Version/s: 1.2.10
    • Fix Version/s: 1.2.12
    • Component/s: Appenders
    • Labels:
      None
    • Environment:
      Windows server 2003

      Description

      Dear sir/madam,

      We are using Log4Net 1.2.10. We encounter the problem that Log4net doesn't continue logging after an event that triggers an appdomain recycle/restart.

      In the global.asax we start the logging with:

      private static readonly ILog log = LogManager.GetLogger(MethodBase.GetCurrentMethod().DeclaringType);

      Logging works flawless when the application is started for the first time. After sometime it might occur that the appdomain gets recycled due to inactivity of the web application. We use the following code in Application_end():

      log.Info("*** Application end ***");

      log4net.LogManager.Shutdown();

      After this function the application gets restarted and the Application_start() method executes and writes new lines to the log. The problem is that the log4net doesn't write the new lines after the restart. Could you explain why log4net might stop working after an appdomain restart of an asp.net2.0 web application? If I want log4net to work properly again I need to restart IIS manually.

      Looking forward to your reply.

      Best regards,

      Richard Nijkamp

        Issue Links

          Activity

          Hide
          Ron Grabowski added a comment -

          What appenders are you using? Maybe you have an exclusive lock on something that is still being kept after the restart. Have you tried using the AdoNetAppender and/or appending the processid to your filename so every restart gets its own file?

          Show
          Ron Grabowski added a comment - What appenders are you using? Maybe you have an exclusive lock on something that is still being kept after the restart. Have you tried using the AdoNetAppender and/or appending the processid to your filename so every restart gets its own file?
          Hide
          Ilpo Juvander added a comment -

          We have also similar situation. We're using rollingfileappender.

          What has helped on some cases is to call on global.asax Xmlconfigurator.ConfigureAndWatch -method on Init(), but this trick does not work 100% of the time. It just stops logging.

          Even restarting IIS does not help. Sometimes logging resumes after renaming the logfile, sometimes not. Same thing happens when adding the processid into it.

          Appender in setup like this:

          <appender name="RollingLogFileAppender" type="log4net.Appender.RollingFileAppender">
          <file value="Webservice.service.txt" />
          <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
          <appendToFile value="true" />
          <rollingStyle value="Size" />
          <maxSizeRollBackups value="10" />
          <maximumFileSize value="1000KB" />
          <staticLogFileName value="false" />
          <layout type="log4net.Layout.PatternLayout">
          <conversionPattern value="%date %-5level %logger (%file:%line) - %message%newline" />
          </layout>
          </appender>

          Nothing really helpfull in the log4net debug after

          log4net: Hierarchy: Shutdown called on Hierarchy [log4net-default-repository]

          Xmlconfigurator entires are never shown and logging stopped.

          On some systems this does not happen at all, on some places it happens all the time. Took a while before I got it in our test environment, but now it happens in there all the time as well...

          Show
          Ilpo Juvander added a comment - We have also similar situation. We're using rollingfileappender. What has helped on some cases is to call on global.asax Xmlconfigurator.ConfigureAndWatch -method on Init(), but this trick does not work 100% of the time. It just stops logging. Even restarting IIS does not help. Sometimes logging resumes after renaming the logfile, sometimes not. Same thing happens when adding the processid into it. Appender in setup like this: <appender name="RollingLogFileAppender" type="log4net.Appender.RollingFileAppender"> <file value="Webservice.service.txt" /> <lockingModel type="log4net.Appender.FileAppender+MinimalLock" /> <appendToFile value="true" /> <rollingStyle value="Size" /> <maxSizeRollBackups value="10" /> <maximumFileSize value="1000KB" /> <staticLogFileName value="false" /> <layout type="log4net.Layout.PatternLayout"> <conversionPattern value="%date %-5level %logger (% file:%line ) - %message%newline" /> </layout> </appender> Nothing really helpfull in the log4net debug after log4net: Hierarchy: Shutdown called on Hierarchy [log4net-default-repository] Xmlconfigurator entires are never shown and logging stopped. On some systems this does not happen at all, on some places it happens all the time. Took a while before I got it in our test environment, but now it happens in there all the time as well...
          Hide
          Matthew Schneider added a comment -

          I have a similar issue in that logging functions fine for an IIS 6.0 ASP.NET 2.0 web service, however all logging ends after a recycle event. Manually recycling the Application Pool causes the failure every time.

          Like Richard, I initiate logging in the global application start event, and log events on application start and end (as well as other places).

          I am using the Rhino.Commons.Logging.RollingSqlliteAppender which inherits from Rhino.Commons.Logging.RollingEmbeddedDatabaseAppender which in turn inherits from the Log4Net AdoNetAppender.

          You can see the code here:
          https://github.com/lorenzomelato/rhino-commons/tree/master/Rhino.Commons/Logging

          Thanks

          Show
          Matthew Schneider added a comment - I have a similar issue in that logging functions fine for an IIS 6.0 ASP.NET 2.0 web service, however all logging ends after a recycle event. Manually recycling the Application Pool causes the failure every time. Like Richard, I initiate logging in the global application start event, and log events on application start and end (as well as other places). I am using the Rhino.Commons.Logging.RollingSqlliteAppender which inherits from Rhino.Commons.Logging.RollingEmbeddedDatabaseAppender which in turn inherits from the Log4Net AdoNetAppender. You can see the code here: https://github.com/lorenzomelato/rhino-commons/tree/master/Rhino.Commons/Logging Thanks
          Hide
          Stefan Bodewig added a comment -

          Can you check whether the problem still exists in 1.2.11?

          Show
          Stefan Bodewig added a comment - Can you check whether the problem still exists in 1.2.11?
          Hide
          Matthew Schneider added a comment -

          Sorry, I should have indicated as much. Yes, the problem still exists in 1.2.11.
          I recompiled the Rhino.Commons.Logging code against the new assembly as well.

          Show
          Matthew Schneider added a comment - Sorry, I should have indicated as much. Yes, the problem still exists in 1.2.11. I recompiled the Rhino.Commons.Logging code against the new assembly as well.
          Hide
          Stefan Bodewig added a comment - - edited

          Are you using attributes for configuration or are you invoking Configure programmatically?

          Probably the latter (I just re-read your "initiate logging" part again).

          If you do so in code: the configure methods in 1.2.11 return a collection of diagnostic messages now (they used to be void methods). Anything useful in there?

          Show
          Stefan Bodewig added a comment - - edited Are you using attributes for configuration or are you invoking Configure programmatically? Probably the latter (I just re-read your "initiate logging" part again). If you do so in code: the configure methods in 1.2.11 return a collection of diagnostic messages now (they used to be void methods). Anything useful in there?
          Hide
          Ilpo Juvander added a comment -

          We have found a workaround: in your webservice class constructor call

          log4net.Config.XmlConfigurator.ConfigureAndWatch(new System.IO.FileInfo(AppDomain.CurrentDomain.SetupInformation.ApplicationBase + "log4net.config"));

          That will reinitialize logging and make it work.

          Show
          Ilpo Juvander added a comment - We have found a workaround: in your webservice class constructor call log4net.Config.XmlConfigurator.ConfigureAndWatch(new System.IO.FileInfo(AppDomain.CurrentDomain.SetupInformation.ApplicationBase + "log4net.config")); That will reinitialize logging and make it work.
          Hide
          Matthew Schneider added a comment -

          I have a logging.config file, which was at one time part of the web.config, but I have recently split it out in a separate file while trying to debug this issue. I have a tag for the XmlConfigurator in my assembly info file, with a referential path to "Logging.config".

          While trying to debug this issue, I also have tried calling log4net.Config.XmlConfigurator.ConfigureAndWatch and log4net.Config.XmlConfigurator.Configure within the global application start event. That is what you would have read above.
          When calling these, I have referenced just "Logging.config" and System.IO.Path.Combine(HttpRuntime.AppDomainAppPath, "Logging.config")) just in case it was losing its path to the application root.

          I'd be happy to try applying the configuration programmatically in a different manner if you could point me to some documentation or a quick example to get me started.

          Show
          Matthew Schneider added a comment - I have a logging.config file, which was at one time part of the web.config, but I have recently split it out in a separate file while trying to debug this issue. I have a tag for the XmlConfigurator in my assembly info file, with a referential path to "Logging.config". While trying to debug this issue, I also have tried calling log4net.Config.XmlConfigurator.ConfigureAndWatch and log4net.Config.XmlConfigurator.Configure within the global application start event. That is what you would have read above. When calling these, I have referenced just "Logging.config" and System.IO.Path.Combine(HttpRuntime.AppDomainAppPath, "Logging.config")) just in case it was losing its path to the application root. I'd be happy to try applying the configuration programmatically in a different manner if you could point me to some documentation or a quick example to get me started.
          Hide
          Ilpo Juvander added a comment -

          Global app events won't work, put the ConfigureAndWatch into your webservice class contructor.

          Note that once it has already failed, you need to reset iis or better yet restart whole computer. Otherwise it will fail again.

          like this:

          public Service()

          { log4net.Config.XmlConfigurator.ConfigureAndWatch(new System.IO.FileInfo(AppDomain.CurrentDomain.SetupInformation.ApplicationBase + "log4net.config")); }
          Show
          Ilpo Juvander added a comment - Global app events won't work, put the ConfigureAndWatch into your webservice class contructor. Note that once it has already failed, you need to reset iis or better yet restart whole computer. Otherwise it will fail again. like this: public Service() { log4net.Config.XmlConfigurator.ConfigureAndWatch(new System.IO.FileInfo(AppDomain.CurrentDomain.SetupInformation.ApplicationBase + "log4net.config")); }
          Hide
          Stefan Bodewig added a comment -

          @Matthiew: ConfigureAndWatch in your application start event was what I was thinking about, and using the full path won't hurt.

          @Ilpo: this is strange as it indicates the re-configuration inside the application start event didn't work.

          I assume turning on internal debugging of log4net still doesn't provide anything useful.

          Show
          Stefan Bodewig added a comment - @Matthiew: ConfigureAndWatch in your application start event was what I was thinking about, and using the full path won't hurt. @Ilpo: this is strange as it indicates the re-configuration inside the application start event didn't work. I assume turning on internal debugging of log4net still doesn't provide anything useful.
          Hide
          Ilpo Juvander added a comment -

          There is still something unfinished when these global app events are triggered on IIS side, class constructor works 100% and we have been now using that successfully for years.

          Debugging just showed that it stops processing these configurations and thinks that is has already done it. It also sometimes caused whole service to hang.

          Show
          Ilpo Juvander added a comment - There is still something unfinished when these global app events are triggered on IIS side, class constructor works 100% and we have been now using that successfully for years. Debugging just showed that it stops processing these configurations and thinks that is has already done it. It also sometimes caused whole service to hang.
          Hide
          Roy Chastain added a comment -

          Just to add my bit. I have (only) one IIS hosted service and I blindly put the call to configure log4Net in the class constructor and it has been working fine across app pool restarts and changes to web.config which also restart the app pool.

          Show
          Roy Chastain added a comment - Just to add my bit. I have (only) one IIS hosted service and I blindly put the call to configure log4Net in the class constructor and it has been working fine across app pool restarts and changes to web.config which also restart the app pool.
          Hide
          Matthew Schneider added a comment -

          Neither Configure or ConfigureAndWatch are working for me in the class constructor. However, I am unable to reset IIS at the moment as Ilpo has suggested; I will try this later.

          The comment "Note that once it has already failed, you need to reset iis or better yet restart whole computer. Otherwise it will fail again." is concerning.

          I'm also curious about the impact of the "AndWatch" functionality if you are triggering it in the class constructor upon every instantiation.

          Show
          Matthew Schneider added a comment - Neither Configure or ConfigureAndWatch are working for me in the class constructor. However, I am unable to reset IIS at the moment as Ilpo has suggested; I will try this later. The comment "Note that once it has already failed, you need to reset iis or better yet restart whole computer. Otherwise it will fail again." is concerning. I'm also curious about the impact of the "AndWatch" functionality if you are triggering it in the class constructor upon every instantiation.
          Hide
          Roy Chastain added a comment -

          I have a singleton class. If you don't, have a singleton, then look at a static flag indicating you have configured log4Net.
          Also, note the AndWatch is simply so that if you edit the config file, log4Net will reconfigure. If you do not want that behavour, leave off the AndWatch.

          Show
          Roy Chastain added a comment - I have a singleton class. If you don't, have a singleton, then look at a static flag indicating you have configured log4Net. Also, note the AndWatch is simply so that if you edit the config file, log4Net will reconfigure. If you do not want that behavour, leave off the AndWatch.
          Hide
          Stefan Bodewig added a comment -

          I can easily see how the Application_End event may end up not cleaning up everything if stopping the appenders takes too long.

          But so far I've always trusted the Application_Start events. Ilpo and Roy, any idea why this wouldn't work?

          Show
          Stefan Bodewig added a comment - I can easily see how the Application_End event may end up not cleaning up everything if stopping the appenders takes too long. But so far I've always trusted the Application_Start events. Ilpo and Roy, any idea why this wouldn't work?
          Hide
          Ilpo Juvander added a comment -

          No idea why we got it working in class constructor, but it is working and has been working. We have app pools recycled quite often due to issus on another 3rd party component.

          When you are testing this, have a clean IIS process. If it has already failed, restart whole computer and try only then. It leaves something behind. Have not debugged what that is, but there is something which is not cleaned by app pool restart.

          Show
          Ilpo Juvander added a comment - No idea why we got it working in class constructor, but it is working and has been working. We have app pools recycled quite often due to issus on another 3rd party component. When you are testing this, have a clean IIS process. If it has already failed, restart whole computer and try only then. It leaves something behind. Have not debugged what that is, but there is something which is not cleaned by app pool restart.
          Hide
          Matthew Schneider added a comment -

          Ilpo and Roy, how and where are you instantiating your loggers? Like Richard did above, and only in global? Multiple places? What is the scope of your logger?

          I wonder how IIS is managing the lifetime of the object, and if this is affecting how it behaves during a recycle?

          Show
          Matthew Schneider added a comment - Ilpo and Roy, how and where are you instantiating your loggers? Like Richard did above, and only in global? Multiple places? What is the scope of your logger? I wonder how IIS is managing the lifetime of the object, and if this is affecting how it behaves during a recycle?
          Hide
          Ilpo Juvander added a comment -

          On all webservice classes that need logging like this:

          public class Service : System.Web.Services.WebService
          {
          private static readonly log4net.ILog log = log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);

          public Service()

          { log4net.Config.XmlConfigurator.ConfigureAndWatch(new System.IO.FileInfo(AppDomain.CurrentDomain.SetupInformation.ApplicationBase + "log4net.config")); }

          Other classes logging work just fine after this.

          Show
          Ilpo Juvander added a comment - On all webservice classes that need logging like this: public class Service : System.Web.Services.WebService { private static readonly log4net.ILog log = log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType); public Service() { log4net.Config.XmlConfigurator.ConfigureAndWatch(new System.IO.FileInfo(AppDomain.CurrentDomain.SetupInformation.ApplicationBase + "log4net.config")); } Other classes logging work just fine after this.
          Hide
          Roy Chastain added a comment -

          Stefan, I have no idea. I never tried it the other way.

          Matthew, I do not even have the global appstart and append methods in my code. I have a IIS hosted web service (.svc). In the constructor for the class that implments the service, I make reference to a singleton class that holds a lot of redundant and static data. The singleton class constructor calls the log4Net configure as its first operation. I create a static logger for each class that I have logging in. I have wrapper code that can determine the object instansation of the class so that each instansation of the class is displayed differently in the log.

          An interesting, but not extermely suprising, note is that even though I create the logger for the service implementation class before configuration log4Net, it still works and logs entries correctly for the first creation of the service class.

          BTW. I do NOT call the log4Net "shutdown" method. I have used log4Net in about 20 self-hosted services and several desktop applications and now one IIS hosted service, and I have never called that method. I have not looked at the code to see what it does and why I would call it, but I cannot say that I have seen a down side to not calling it.

          Show
          Roy Chastain added a comment - Stefan, I have no idea. I never tried it the other way. Matthew, I do not even have the global appstart and append methods in my code. I have a IIS hosted web service (.svc). In the constructor for the class that implments the service, I make reference to a singleton class that holds a lot of redundant and static data. The singleton class constructor calls the log4Net configure as its first operation. I create a static logger for each class that I have logging in. I have wrapper code that can determine the object instansation of the class so that each instansation of the class is displayed differently in the log. An interesting, but not extermely suprising, note is that even though I create the logger for the service implementation class before configuration log4Net, it still works and logs entries correctly for the first creation of the service class. BTW. I do NOT call the log4Net "shutdown" method. I have used log4Net in about 20 self-hosted services and several desktop applications and now one IIS hosted service, and I have never called that method. I have not looked at the code to see what it does and why I would call it, but I cannot say that I have seen a down side to not calling it.
          Hide
          Matthew Schneider added a comment -

          I rebooted, the logging started fine. I manually recycled the application pool, and it no longer logs.

          Show
          Matthew Schneider added a comment - I rebooted, the logging started fine. I manually recycled the application pool, and it no longer logs.
          Hide
          Jim Moore added a comment - - edited

          I see this issue as well. Exactly the same, IIS 6, asp.net 4.0, log4Net 1.2.11. I'm using the standard RollingFileAppender.

          Show
          Jim Moore added a comment - - edited I see this issue as well. Exactly the same, IIS 6, asp.net 4.0, log4Net 1.2.11. I'm using the standard RollingFileAppender.
          Hide
          Phil Yardley added a comment -

          We've just come across this issue when hosting in Azure (IIS7.5) - logging stops on all our instances until we "kick" the application by changing the web.config.

          A bit concerned that this bug > 12 months old and makes the module useless on a daily basis.

          Show
          Phil Yardley added a comment - We've just come across this issue when hosting in Azure (IIS7.5) - logging stops on all our instances until we "kick" the application by changing the web.config. A bit concerned that this bug > 12 months old and makes the module useless on a daily basis.
          Hide
          Dominik Psenner added a comment -

          I am no expert on IIS web applications, but it would look like a misconfigured log4net configuration and/or a missing initialization. If logging starts by changing the web.config, log4net is "watching" for changes in the web.config and respawns the appenders when that happens. This means that either:

          • log4net gets never started
          • log4net gets stopped and not restarted

          Thus - in theory - adding an initialization in the right spot alike the one in comment https://issues.apache.org/jira/browse/LOG4NET-178?focusedCommentId=13127649&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-13127649 could fix the issue.

          Show
          Dominik Psenner added a comment - I am no expert on IIS web applications, but it would look like a misconfigured log4net configuration and/or a missing initialization. If logging starts by changing the web.config, log4net is "watching" for changes in the web.config and respawns the appenders when that happens. This means that either: log4net gets never started log4net gets stopped and not restarted Thus - in theory - adding an initialization in the right spot alike the one in comment https://issues.apache.org/jira/browse/LOG4NET-178?focusedCommentId=13127649&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-13127649 could fix the issue.
          Hide
          Lazy Developer added a comment -

          Despite of these IIS settings processModel.idleTimeout = 0 and recycling.periodicRestart.time = 0, we have the same issue (Azure, IIS 7.5, ADONetAppender, separate log4net.config to web.config). Our temporary solution is pinging the page every N minutes.

          Show
          Lazy Developer added a comment - Despite of these IIS settings processModel.idleTimeout = 0 and recycling.periodicRestart.time = 0, we have the same issue (Azure, IIS 7.5, ADONetAppender, separate log4net.config to web.config). Our temporary solution is pinging the page every N minutes.
          Hide
          Lazy Developer added a comment -

          Hi Everyone,

          Thanks the tip from Dominik, he's right, it's completely about CONFIGURATION.

          We turned on the log4net internal logging (log4net.Internal.Debug=true...etc.) for more details. The root of our problem is about forgetting this code log4net.Config.XmlConfigurator.Configure() in Global.asax.cs (Application_Start). REMOVE IT!

          We have separate log4net.config from web.config and in the AssemblyInfo.cs we've already have this code [assembly: log4net.Config.XmlConfigurator(ConfigFile = "log4net.config", Watch = true)]. It must be enough.

          When the recycle occured (Application_Start is activated) the log4net tried to looking for its configuration in web.config instead of log4net.config (because of the mentioned code log4net.Config.XmlConfigurator.Configure()). It's certainly failed, therefore stop logging.

          Show
          Lazy Developer added a comment - Hi Everyone, Thanks the tip from Dominik, he's right, it's completely about CONFIGURATION. We turned on the log4net internal logging (log4net.Internal.Debug=true...etc.) for more details. The root of our problem is about forgetting this code log4net.Config.XmlConfigurator.Configure() in Global.asax.cs (Application_Start). REMOVE IT! We have separate log4net.config from web.config and in the AssemblyInfo.cs we've already have this code [assembly: log4net.Config.XmlConfigurator(ConfigFile = "log4net.config", Watch = true)] . It must be enough. When the recycle occured (Application_Start is activated) the log4net tried to looking for its configuration in web.config instead of log4net.config (because of the mentioned code log4net.Config.XmlConfigurator.Configure()). It's certainly failed, therefore stop logging.
          Hide
          Dominik Psenner added a comment -

          Glad to hear you were able to sort out this nasty problem. Can this bug therefore be closed?

          Show
          Dominik Psenner added a comment - Glad to hear you were able to sort out this nasty problem. Can this bug therefore be closed?
          Hide
          Ilpo Juvander added a comment -

          Above configuration is not the whole truth. What we originally had was exactly like it is for desktop application, using this [assembly: log4net.Config.XmlConfigurator(ConfigFile = "log4net.config", Watch = true)]. It does not really matter what the file name is, logging just ends at some point when IIS is recycling application pools.

          There is some timing issue how this configuration/shutdown is handled. Application start seems to happen before previous shutdown is called thus even new instance gets logging shutdown. Using configuration call from class constructor is late enough so that it really does the initialization for new instance and does not get this shutdown call from previous application pool. We have used this method now for years in hundreds of installations on different environments and works 100% of the time.

          Sometimes this happens, sometimes not. On some environments this happens immediately, on some it takes a while to reappear, but it will eventually be there.

          Show
          Ilpo Juvander added a comment - Above configuration is not the whole truth. What we originally had was exactly like it is for desktop application, using this [assembly: log4net.Config.XmlConfigurator(ConfigFile = "log4net.config", Watch = true)] . It does not really matter what the file name is, logging just ends at some point when IIS is recycling application pools. There is some timing issue how this configuration/shutdown is handled. Application start seems to happen before previous shutdown is called thus even new instance gets logging shutdown. Using configuration call from class constructor is late enough so that it really does the initialization for new instance and does not get this shutdown call from previous application pool. We have used this method now for years in hundreds of installations on different environments and works 100% of the time. Sometimes this happens, sometimes not. On some environments this happens immediately, on some it takes a while to reappear, but it will eventually be there.
          Hide
          Dominik Psenner added a comment - - edited

          So the general consensus is that the issue is:

          1] IIS (7.5?) specific
          2] a timing problem caused by misplaced shutdown / start events
          3] solvable with a "manual" reconfiguration of log4net in the right spot
          4] not solvable in log4net itself since log4net has to handle events when they are raised

          If these conditions are met I would close this issue with resolution "invalid" and add a new FAQ entry at http://logging.apache.org/log4net/release/faq.html describing the issue and a rather detailed description how it can be fixed. To be able to do that, would one of you guys please write down an answer to the question:

          "Why does my IIS hosted web application stop logging after some time?"

          By the way: has someone tested this scenario for IIS 8.0?

          Show
          Dominik Psenner added a comment - - edited So the general consensus is that the issue is: 1] IIS (7.5?) specific 2] a timing problem caused by misplaced shutdown / start events 3] solvable with a "manual" reconfiguration of log4net in the right spot 4] not solvable in log4net itself since log4net has to handle events when they are raised If these conditions are met I would close this issue with resolution "invalid" and add a new FAQ entry at http://logging.apache.org/log4net/release/faq.html describing the issue and a rather detailed description how it can be fixed. To be able to do that, would one of you guys please write down an answer to the question: "Why does my IIS hosted web application stop logging after some time?" By the way: has someone tested this scenario for IIS 8.0?
          Hide
          Lazy Developer added a comment -

          We tested it in these environments (and it's working):
          DEV/INT: Windows 2008 R2, IIS 7.5, SQL 2008 R2
          UAT/LIVE: Azure Cloud Services (Windows 2012, IIS 8), SQL Azure - it should be working the normal IIS as well.

          All I can suggest is turning on the log4net debugging features and fix all ERROR (in our case it was incorrect configuration). If there's no ERROR shows in the log4net debug log then it should be working.

          Show
          Lazy Developer added a comment - We tested it in these environments (and it's working): DEV/INT: Windows 2008 R2, IIS 7.5, SQL 2008 R2 UAT/LIVE: Azure Cloud Services (Windows 2012, IIS 8), SQL Azure - it should be working the normal IIS as well. All I can suggest is turning on the log4net debugging features and fix all ERROR (in our case it was incorrect configuration). If there's no ERROR shows in the log4net debug log then it should be working.
          Hide
          Matthew Schneider added a comment -

          Dominik:
          1] This definitely happens in IIS 6.0 as well as 7.5, I can't speak to 8.0.
          2] This is likely true, it probably has something to do with the fact that IIS runs a (shadow?) copy of the deployed code, not the code itself. Thus it might be starting a new instance (copy) while a previous instance (different copy) is terminating.
          3] I've not had any luck with Ilpo's approach, but perhaps with another attempt, I might... (I just don't have the time at the moment).
          4] I don't know that I agree that this is not solvable in log4net itself. I might agree that it is cheaper or easier to work around the issue (and that might be the best thing to do), but I suspect there is a way to cope with this if the right domain expert were to understand the problem correctly. It seems like this is a valid bug, just with a workaround instead of a fix.

          Show
          Matthew Schneider added a comment - Dominik: 1] This definitely happens in IIS 6.0 as well as 7.5, I can't speak to 8.0. 2] This is likely true, it probably has something to do with the fact that IIS runs a (shadow?) copy of the deployed code, not the code itself. Thus it might be starting a new instance (copy) while a previous instance (different copy) is terminating. 3] I've not had any luck with Ilpo's approach, but perhaps with another attempt, I might... (I just don't have the time at the moment). 4] I don't know that I agree that this is not solvable in log4net itself. I might agree that it is cheaper or easier to work around the issue (and that might be the best thing to do), but I suspect there is a way to cope with this if the right domain expert were to understand the problem correctly. It seems like this is a valid bug, just with a workaround instead of a fix.
          Hide
          Dominik Psenner added a comment - - edited

          The general agreement is that this issue is better solved with workarounds. Therefore I just commited a new FAQ entry to the website as revision 839974:

          http://logging.apache.org/log4net/release/faq.html#trouble-webapp-stops-logging

          If you run into this issue please follow the steps there. If those do not solve your problem or you think there is something missing in the FAQ entry or you know a log4net-only solution that works feel free to reopen the bug and post a patch.

          Show
          Dominik Psenner added a comment - - edited The general agreement is that this issue is better solved with workarounds. Therefore I just commited a new FAQ entry to the website as revision 839974: http://logging.apache.org/log4net/release/faq.html#trouble-webapp-stops-logging If you run into this issue please follow the steps there. If those do not solve your problem or you think there is something missing in the FAQ entry or you know a log4net-only solution that works feel free to reopen the bug and post a patch.
          Hide
          Kamran added a comment -

          It is still not resolved in 1.2.13
          As a workaround i tried added line in global.asax Application_Start event (instead of class constructor as i think it will have performance consequences) but there seems to be no use

          Show
          Kamran added a comment - It is still not resolved in 1.2.13 As a workaround i tried added line in global.asax Application_Start event (instead of class constructor as i think it will have performance consequences) but there seems to be no use
          Hide
          Brian Baker added a comment -

          In our case we deduced that this was a result of "overlapped recycling" as described in the TechNet article How Worker Process Recycling Works (IIS 6.0) (note that although the article is for IIS 6, the same principle applies to later versions). By setting DisallowOverlappingRotation to true for our application pool we resolved the issue. There are some downsides to disabling overlapped recycling, so be sure you understand the ramifications before using this workaround.

          Show
          Brian Baker added a comment - In our case we deduced that this was a result of "overlapped recycling" as described in the TechNet article How Worker Process Recycling Works (IIS 6.0) (note that although the article is for IIS 6, the same principle applies to later versions). By setting DisallowOverlappingRotation to true for our application pool we resolved the issue. There are some downsides to disabling overlapped recycling, so be sure you understand the ramifications before using this workaround.
          Hide
          Dominik Psenner added a comment -

          Thanks Brian, I'm glad somebody had the time to troubleshoot the root cause. To me this confirms what I pointed out as 2] in the comment on the 27. nov 2012. We should probably enhance the faq to include your valuable contribution.

          Show
          Dominik Psenner added a comment - Thanks Brian, I'm glad somebody had the time to troubleshoot the root cause. To me this confirms what I pointed out as 2] in the comment on the 27. nov 2012. We should probably enhance the faq to include your valuable contribution.
          Hide
          Kamran added a comment - - edited

          My question is why this is marked as resolved in 1.2.12 even if it is still exists in latest version (currently 1.2.13) version.
          I can't allowed to change DisallowOverlappingRotation on my production system. This has to be reopened and properly handled.I have logging in mysql db as well as in file. Same problem doesn't appear in RollingFileAppender. I have number of web services. And I don't want's to put log4net configure in each service constructor as it will be a performance impact.
          Any Idea about how can i manage it in Application_start event of glabal.asax.cs

          Show
          Kamran added a comment - - edited My question is why this is marked as resolved in 1.2.12 even if it is still exists in latest version (currently 1.2.13) version. I can't allowed to change DisallowOverlappingRotation on my production system. This has to be reopened and properly handled.I have logging in mysql db as well as in file. Same problem doesn't appear in RollingFileAppender. I have number of web services. And I don't want's to put log4net configure in each service constructor as it will be a performance impact. Any Idea about how can i manage it in Application_start event of glabal.asax.cs
          Hide
          Kamran added a comment -

          But it is not practical to put configuration call in each of class constructor as it will have performance impact.

          Show
          Kamran added a comment - But it is not practical to put configuration call in each of class constructor as it will have performance impact.
          Hide
          Dominik Psenner added a comment - - edited

          Sorry Kamran, the consensus was that this issue can be fixed only by disabling the overlapping rotation in the IIS configuration and it is the only fix available. However, contributions are always welcome and if you find a better way I want to encourage you to contribute your ideas!

          For future readers, the issue arises by IIS that allows overlapping rotates. The web application is then restarted without unloading log4net, but log4net receives a "start" event while it is still running and right after that a "stop" event which it handles by shutting down. Since the "start" event was already sent it will be generated only with the next restart or reload and in the meantime no logging happens at all. Configuring IIS to DisallowOverlappingRotation=true makes sure that the "start" and "stop" events arrive in order.

          Show
          Dominik Psenner added a comment - - edited Sorry Kamran, the consensus was that this issue can be fixed only by disabling the overlapping rotation in the IIS configuration and it is the only fix available. However, contributions are always welcome and if you find a better way I want to encourage you to contribute your ideas! For future readers, the issue arises by IIS that allows overlapping rotates. The web application is then restarted without unloading log4net, but log4net receives a "start" event while it is still running and right after that a "stop" event which it handles by shutting down. Since the "start" event was already sent it will be generated only with the next restart or reload and in the meantime no logging happens at all. Configuring IIS to DisallowOverlappingRotation=true makes sure that the "start" and "stop" events arrive in order.
          Hide
          Gert Kello added a comment -

          Hi.

          I can't fully agree with the conclusion. The start and stop events should be executed in different app domains so one should not interfere with another at C# code level.

          I made a very simple test web site, which produces following output

          2015-06-11 15:58:53,514 [5->/LM/W3SVC/1/ROOT/test-1-130785010739331037] - Request nr 37 served
          2015-06-11 15:58:54,126 [10->/LM/W3SVC/1/ROOT/test-1-130785010739331037] - Request nr 38 served
          2015-06-11 15:58:55,121 [1->/LM/W3SVC/1/ROOT/test-1-130785011348421940] - App started
          2015-06-11 15:58:55,165 [5->/LM/W3SVC/1/ROOT/test-1-130785011348421940] - Request nr 1 served
          2015-06-11 15:58:55,718 [5->/LM/W3SVC/1/ROOT/test-1-130785011348421940] - Request nr 2 served
          2015-06-11 15:58:55,872 [8->/LM/W3SVC/1/ROOT/test-1-130785010739331037] - Shutting down: HostingEnvironment
          2015-06-11 15:59:01,605 [5->/LM/W3SVC/1/ROOT/test-1-130785011348421940] - Request nr 3 served
          

          where logging pattern is

          "%date [%thread->%appdomain] - %message%newline"
          

          As You can see the app domain names are different for "app start" and "shutting down" messages.
          And the logging system remained functional after the shut down on LogManager was called

          Code in global.asax:

              void Application_Start(object sender, EventArgs e)
              {
                  log4net.Config.XmlConfigurator.Configure();
                  log4net.ILog log = log4net.LogManager.GetLogger(this.GetType());
                  log.Info("App started");
              }
          
              void Application_End(object sender, EventArgs e)
              {
                  log4net.ILog log = log4net.LogManager.GetLogger(this.GetType());
                  log.InfoFormat("Shutting down: {0}", System.Web.Hosting.HostingEnvironment.ShutdownReason);
                  log4net.LogManager.Shutdown();
              }
          

          Am I missing something in my test?

          Show
          Gert Kello added a comment - Hi. I can't fully agree with the conclusion. The start and stop events should be executed in different app domains so one should not interfere with another at C# code level. I made a very simple test web site, which produces following output 2015-06-11 15:58:53,514 [5->/LM/W3SVC/1/ROOT/test-1-130785010739331037] - Request nr 37 served 2015-06-11 15:58:54,126 [10->/LM/W3SVC/1/ROOT/test-1-130785010739331037] - Request nr 38 served 2015-06-11 15:58:55,121 [1->/LM/W3SVC/1/ROOT/test-1-130785011348421940] - App started 2015-06-11 15:58:55,165 [5->/LM/W3SVC/1/ROOT/test-1-130785011348421940] - Request nr 1 served 2015-06-11 15:58:55,718 [5->/LM/W3SVC/1/ROOT/test-1-130785011348421940] - Request nr 2 served 2015-06-11 15:58:55,872 [8->/LM/W3SVC/1/ROOT/test-1-130785010739331037] - Shutting down: HostingEnvironment 2015-06-11 15:59:01,605 [5->/LM/W3SVC/1/ROOT/test-1-130785011348421940] - Request nr 3 served where logging pattern is "%date [%thread->%appdomain] - %message%newline" As You can see the app domain names are different for "app start" and "shutting down" messages. And the logging system remained functional after the shut down on LogManager was called Code in global.asax: void Application_Start(object sender, EventArgs e) { log4net.Config.XmlConfigurator.Configure(); log4net.ILog log = log4net.LogManager.GetLogger( this .GetType()); log.Info( "App started" ); } void Application_End(object sender, EventArgs e) { log4net.ILog log = log4net.LogManager.GetLogger( this .GetType()); log.InfoFormat( "Shutting down: {0}" , System .Web.Hosting.HostingEnvironment.ShutdownReason); log4net.LogManager.Shutdown(); } Am I missing something in my test?
          Hide
          Kamran added a comment -

          One more thing i want to ask is that this problem will also be there if I upgrade my application to .net 4.0 ?

          Show
          Kamran added a comment - One more thing i want to ask is that this problem will also be there if I upgrade my application to .net 4.0 ?
          Hide
          Kamran added a comment -

          I have tried with in global.asax.cs
          protected void Application_Start(object sender, EventArgs e)

          { log4net.Config.XmlConfigurator.ConfigureAndWatch(new System.IO.FileInfo(AppDomain.CurrentDomain.SetupInformation.ApplicationBase + "log4net.config")); }

          But problem still exists.

          should I try with adding
          void Application_End(object sender, EventArgs e)

          { log4net.LogManager.Shutdown(); }
          Show
          Kamran added a comment - I have tried with in global.asax.cs protected void Application_Start(object sender, EventArgs e) { log4net.Config.XmlConfigurator.ConfigureAndWatch(new System.IO.FileInfo(AppDomain.CurrentDomain.SetupInformation.ApplicationBase + "log4net.config")); } But problem still exists. should I try with adding void Application_End(object sender, EventArgs e) { log4net.LogManager.Shutdown(); }
          Hide
          Brian Baker added a comment -

          It isn't so much that events are happening out of order – it is more of an issue of having multiple processes trying to write to the same file. If you refer to the link I posted in the previous comment, you can read a little bit more about how worker process recycling works. Essentially, when IIS decides to recycle the app pool, it will spin up a new process and when the new process is ready, IIS will start sending HTTP requests to it and start draining the connections from the original process. If the requests are non-trivial and take a little time to complete, this will result in two IIS worker processes running simultaneously. By default, the file appender used by log4net in the first process will have an exclusive file lock on the log file, so when the second process attempts to start locking it won't be able to get a lock on the file.

          You could also see from this explanation why putting an initialization step in the application start event is not reliable. Chances are, if your app is under constant load, that the log file will still be locked from the first process when the second one fires its start event. An initialization in BeginRequest would eventually work but would surely have to much overhead, I would think.

          I suppose you could also try the approaches in the FAQ entry "How do I get multiple process to log to the same file?" although we did not try any of those.

          Alternatively, you could configure the log file name to include the process id so that there would not be a conflict on the file name. However, this is usually not desirable from an operations perspective.

          Show
          Brian Baker added a comment - It isn't so much that events are happening out of order – it is more of an issue of having multiple processes trying to write to the same file. If you refer to the link I posted in the previous comment, you can read a little bit more about how worker process recycling works. Essentially, when IIS decides to recycle the app pool, it will spin up a new process and when the new process is ready, IIS will start sending HTTP requests to it and start draining the connections from the original process. If the requests are non-trivial and take a little time to complete, this will result in two IIS worker processes running simultaneously. By default, the file appender used by log4net in the first process will have an exclusive file lock on the log file, so when the second process attempts to start locking it won't be able to get a lock on the file. You could also see from this explanation why putting an initialization step in the application start event is not reliable. Chances are, if your app is under constant load, that the log file will still be locked from the first process when the second one fires its start event. An initialization in BeginRequest would eventually work but would surely have to much overhead, I would think. I suppose you could also try the approaches in the FAQ entry "How do I get multiple process to log to the same file?" although we did not try any of those. Alternatively, you could configure the log file name to include the process id so that there would not be a conflict on the file name. However, this is usually not desirable from an operations perspective.
          Hide
          Kamran added a comment - - edited

          Oops. I have not much used log4net before the current project and have find so much issues. In-fact I have written a logging framework myself for some previous organization and there isn't even a single problem like here. This problem started to appear when we have added a adonet appender to also log data to mysql database other then a text file via rollingfileappender.I obviously will not do processid wise solution as in my web application it will be a hell to analyze logs in different files

          Show
          Kamran added a comment - - edited Oops. I have not much used log4net before the current project and have find so much issues. In-fact I have written a logging framework myself for some previous organization and there isn't even a single problem like here. This problem started to appear when we have added a adonet appender to also log data to mysql database other then a text file via rollingfileappender.I obviously will not do processid wise solution as in my web application it will be a hell to analyze logs in different files
          Hide
          Dominik Psenner added a comment - - edited

          Glad to read people are working on this issue. I have no idea what causes Kamrans application to fail. The RollingFileAppender is a major mess that I already tried to clean up with a rewrite from scratch. Unfortunately it is not finished yet and won't be anytime soon because there is so little sparetime. Kamran, given that you have written your own logging framework you hopefully work out what's going on. Whatever the issues are you find, please feed them back and contribute your ideas. Best would be a patch or concept that fixes or explains the issue. Now that there is someone who can reproduce the symptoms I hope for the best.

          Show
          Dominik Psenner added a comment - - edited Glad to read people are working on this issue. I have no idea what causes Kamrans application to fail. The RollingFileAppender is a major mess that I already tried to clean up with a rewrite from scratch. Unfortunately it is not finished yet and won't be anytime soon because there is so little sparetime. Kamran, given that you have written your own logging framework you hopefully work out what's going on. Whatever the issues are you find, please feed them back and contribute your ideas. Best would be a patch or concept that fixes or explains the issue. Now that there is someone who can reproduce the symptoms I hope for the best.
          Hide
          Kamran added a comment - - edited

          There is no doubt problem is during App domain recycle.
          One error I found from log4net debug log is about my adonet appender setting is

          ERROR XmlHierarchyConfigurator: Cannot find Property [immediateFlush] to set object on [log4net.Appender.AdoNetAppender]

          My adonet appender settings look like

          <appender name="AdoNetAppender" type="log4net.Appender.AdoNetAppender">
          <immediateFlush value="true" />
          <bufferSize value="0" />
          ....

          So now i am commenting out immediateFlush property (which might have been copied from RollingFileAppender Settings) and will see if the problem still exists or not

          Show
          Kamran added a comment - - edited There is no doubt problem is during App domain recycle. One error I found from log4net debug log is about my adonet appender setting is ERROR XmlHierarchyConfigurator: Cannot find Property [immediateFlush] to set object on [log4net.Appender.AdoNetAppender] My adonet appender settings look like <appender name="AdoNetAppender" type="log4net.Appender.AdoNetAppender"> <immediateFlush value="true" /> <bufferSize value="0" /> .... So now i am commenting out immediateFlush property (which might have been copied from RollingFileAppender Settings) and will see if the problem still exists or not
          Hide
          Kamran added a comment - - edited

          Removing immediateFlush property doesn't effect anything.
          What I see is following Last error after which error logging stops

          log4net:ERROR [AdoNetAppender] ErrorCode: GenericFailure. Exception while writing to database
          MySql.Data.MySqlClient.MySqlException: Fatal error encountered during command execution. ---> System.IO.IOException: Unable to write data to the transport connection: An established connection was aborted by the software in your host machine. ---> System.Net.Sockets.SocketException: An established connection was aborted by the software in your host machine
          at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
          at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)
          — End of inner exception stack trace —
          at MyNetworkStream.HandleOrRethrowException(Exception e)
          at MyNetworkStream.Write(Byte[] buffer, Int32 offset, Int32 count)
          at MySql.Data.MySqlClient.TimedStream.Write(Byte[] buffer, Int32 offset, Int32 count)
          at MySql.Data.MySqlClient.MySqlStream.SendPacket(MySqlPacket packet)
          at MySql.Data.MySqlClient.NativeDriver.ExecutePacket(MySqlPacket packetToExecute)
          at MySql.Data.MySqlClient.NativeDriver.SendQuery(MySqlPacket queryPacket)
          at MySql.Data.MySqlClient.Driver.SendQuery(MySqlPacket p)
          at MySql.Data.MySqlClient.Statement.ExecuteNext()
          at MySql.Data.MySqlClient.PreparableStatement.Execute()
          at MySql.Data.MySqlClient.MySqlCommand.ExecuteReader(CommandBehavior behavior)
          — End of inner exception stack trace —
          at MySql.Data.MySqlClient.MySqlCommand.ExecuteReader(CommandBehavior behavior)
          at MySql.Data.MySqlClient.MySqlCommand.ExecuteNonQuery()
          at MySql.Data.MySqlClient.MySqlConnection.BeginTransaction(IsolationLevel iso)
          at MySql.Data.MySqlClient.MySqlConnection.BeginDbTransaction(IsolationLevel isolationLevel)
          at System.Data.Common.DbConnection.System.Data.IDbConnection.BeginTransaction()
          at log4net.Appender.AdoNetAppender.SendBuffer(LoggingEvent[] events)

          So in my adonetappender setting i am adding following property
          <reconnectOnError value="true" />
          and will see if it continue to logging or not

          Show
          Kamran added a comment - - edited Removing immediateFlush property doesn't effect anything. What I see is following Last error after which error logging stops log4net:ERROR [AdoNetAppender] ErrorCode: GenericFailure. Exception while writing to database MySql.Data.MySqlClient.MySqlException: Fatal error encountered during command execution. ---> System.IO.IOException: Unable to write data to the transport connection: An established connection was aborted by the software in your host machine. ---> System.Net.Sockets.SocketException: An established connection was aborted by the software in your host machine at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags) at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size) — End of inner exception stack trace — at MyNetworkStream.HandleOrRethrowException(Exception e) at MyNetworkStream.Write(Byte[] buffer, Int32 offset, Int32 count) at MySql.Data.MySqlClient.TimedStream.Write(Byte[] buffer, Int32 offset, Int32 count) at MySql.Data.MySqlClient.MySqlStream.SendPacket(MySqlPacket packet) at MySql.Data.MySqlClient.NativeDriver.ExecutePacket(MySqlPacket packetToExecute) at MySql.Data.MySqlClient.NativeDriver.SendQuery(MySqlPacket queryPacket) at MySql.Data.MySqlClient.Driver.SendQuery(MySqlPacket p) at MySql.Data.MySqlClient.Statement.ExecuteNext() at MySql.Data.MySqlClient.PreparableStatement.Execute() at MySql.Data.MySqlClient.MySqlCommand.ExecuteReader(CommandBehavior behavior) — End of inner exception stack trace — at MySql.Data.MySqlClient.MySqlCommand.ExecuteReader(CommandBehavior behavior) at MySql.Data.MySqlClient.MySqlCommand.ExecuteNonQuery() at MySql.Data.MySqlClient.MySqlConnection.BeginTransaction(IsolationLevel iso) at MySql.Data.MySqlClient.MySqlConnection.BeginDbTransaction(IsolationLevel isolationLevel) at System.Data.Common.DbConnection.System.Data.IDbConnection.BeginTransaction() at log4net.Appender.AdoNetAppender.SendBuffer(LoggingEvent[] events) So in my adonetappender setting i am adding following property <reconnectOnError value="true" /> and will see if it continue to logging or not
          Hide
          Dominik Psenner added a comment -

          Beware, there is LOG4NET-442 interfering with reconnectOnError if you are using .NET 4.5.1. See this FAQ entry:

          https://logging.apache.org/log4net/release/faq.html#adonet-doesnt-reconnect

          Show
          Dominik Psenner added a comment - Beware, there is LOG4NET-442 interfering with reconnectOnError if you are using .NET 4.5.1. See this FAQ entry: https://logging.apache.org/log4net/release/faq.html#adonet-doesnt-reconnect
          Hide
          Kamran added a comment - - edited

          Ok.
          I have at the moment .net 3.5 application.Hopefully this bug will be fixed in some upcoming version (which i don't know if planned or not after 1.2.13.0)

          Show
          Kamran added a comment - - edited Ok. I have at the moment .net 3.5 application.Hopefully this bug will be fixed in some upcoming version (which i don't know if planned or not after 1.2.13.0)
          Hide
          Kamran added a comment - - edited

          Eventually looks like i were able to continuously log even after app domain recycle after putting <reconnectOnError value="true" /> in my log4net settings of adonetappender.
          Sharing this so that other's might also take care of these settings.

          Show
          Kamran added a comment - - edited Eventually looks like i were able to continuously log even after app domain recycle after putting <reconnectOnError value="true" /> in my log4net settings of adonetappender. Sharing this so that other's might also take care of these settings.

            People

            • Assignee:
              Dominik Psenner
              Reporter:
              Richard Nijkamp
            • Votes:
              5 Vote for this issue
              Watchers:
              9 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development