关于Application_End 与 Application_Start事件触发情况的测试

测试项目搭建

定义一个简单的Mvc项目，有如下文件：

（1）

public class Startup
{
    public void Configuration(IAppBuilder app)
    {
        app.Run(context =>
        {
            return Task.Run(
                async () => {
                    await Task.Delay(600);
                    await context.Response.WriteAsync("Hello, world." + context.Request.Uri);
                });
        });
    }
}

（2）

public class Global : System.Web.HttpApplication
{
    protected void Application_Start(object sender, EventArgs e)
    {
        DebugUtils.Log("Application_Start");

        Task.Run(() => { DebugUtils.beginLog($"bugLog.txt"); });

        for (long i = 0; i < 10000000000; i++) ;

        DebugUtils.Log("Application_Start finished");
    }


    protected void Application_End(object sender, EventArgs e)
    {
        DebugUtils.Log("Application_End");

        for (long i = 0; i < 10000000000; i++) ;

        DebugUtils.Log("Application_End finished");
    }
}

（3）

public class DebugUtils
{

    public static ConcurrentQueue<string> queue = new ConcurrentQueue<string>();

    public static void beginLog(string fileName)
    {
        string dirPath = "G:\c#\www\debugLog\";
        if (!Directory.Exists(dirPath))
            Directory.CreateDirectory(dirPath);

        using (FileStream fs = new FileStream(dirPath + "/" + fileName, FileMode.Append))
        {
            using (StreamWriter sw = new StreamWriter(fs))
            {
                string str;
                while (true)
                {
                    if (queue.TryDequeue(out str))
                    {
                        sw.WriteLine(str);
                        sw.Flush();
                    }
                }

            }
        }
    }

    public static void Log(string str)
    {
        queue.Enqueue("[" + DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss fff") + "]--[" + Thread.CurrentThread.ManagedThreadId + "]--" + str);
    }
}

测试

常规操作

将站点部署到IIS上后，依次进行 修改config, bin文件夹，站点关闭、重启，回收线程池 操作，日志里都有Application_End的触发日志。随后访问页面又会有Application_Start的日志记录。

高并发

使用工具模拟请求高并发地访问这个站点

在此期间修改config, 日志文件中只有Application_End的记录，却没有Application_Start的记录。
再次修改config,这次只有Application_Start的记录，却又没有end的了。尝试多次，一直都这样轮替出现。

虽然上面日志中的记录看上去很平常，但是实际情况却不是这样。

---

于是做了如下修改（每次启动都使用新的日志文件）

同样进行了几次config文件的修改，新的日志记录如下

可以看到Application_Start事件并不会等待Application_End执行完毕才触发。

待解决的疑问：

1. 上面测试中情况
   前面使用同一个日志文件时，日志只记录部分，甚至很规律地交替出现，是因为文件被占用吗?

在打开日志文件时刻意抛出异常，网站可以照常访问，但不再记录日志了，所以文件占用异常确实可以导致上述情况。

    public  void beginLog(string fileName)
    {
        string dirPath = "G:\c#\www\debugLog\";
        if (!Directory.Exists(dirPath))
            Directory.CreateDirectory(dirPath);

        throw new Exception("test");

        using (FileStream fs = new FileStream(dirPath + "/" + fileName, FileMode.Append))
        {
            using (StreamWriter sw = new StreamWriter(fs))
            {
                string str;
                while (true)
                {
                    if (queue.TryDequeue(out str))
                    {
                        sw.WriteLine(str);
                        sw.Flush();
                    }
                }

            }
        }
    }

修改日志记录类为非静态类

（1）

public class DebugUtils
{
    public static DebugUtils Instance = new DebugUtils();

    public static ConcurrentQueue<string> queue = new ConcurrentQueue<string>();

    public  void beginLog(string fileName)
    {
        string dirPath = "G:\c#\www\debugLog\";
        if (!Directory.Exists(dirPath))
            Directory.CreateDirectory(dirPath);

        using (FileStream fs = new FileStream(dirPath + "/" + fileName, FileMode.Append))
        {
            using (StreamWriter sw = new StreamWriter(fs))
            {
                string str;
                while (true)
                {
                    if (queue.TryDequeue(out str))
                    {
                        sw.WriteLine(str);
                        sw.Flush();
                    }
                }

            }
        }
    }

    public  void Log(string str, string date)
    {
        queue.Enqueue($"[{ date }]--[{Thread.CurrentThread.ManagedThreadId}]-[{ this.GetHashCode() }]-{str}");
    }
}

（2）

public class Global : System.Web.HttpApplication
{
    protected void Application_Start(object sender, EventArgs e)
    {
        DebugUtils.Instance.Log("Application_Start", DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss fff"));

        Task.Run(() => { DebugUtils.Instance.beginLog($"bugLog{DateTime.Now.ToString("yyyyMMdd-HHmmssfff")}.txt"); });

        for (long i = 0; i < 10000000000; i++) ;

        DebugUtils.Instance.Log("Application_Start finished", DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss fff"));
    }


    protected void Application_End(object sender, EventArgs e)
    {
        DebugUtils.Instance.Log("Application_End", DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss fff"));

        for (long i = 0; i < 10000000000; i++) ;

        DebugUtils.Instance.Log("Application_End finished", DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss fff"));
    }
}

快速地修改了3次config（空格，保存，空格，保存，空格，保存）, 发现日志文件的创建要滞后许多。

重试了一遍，这次也是3次修改，只触发了两次Application_End

在连续修改config的情况下，start事件几乎是立即就触发了，但end事件如果尚有前一个end事件未执行完成，新的end事件会延后触发。

在end事件中增加代码记录end的触发原因

        try
        {
            HttpRuntime runtime = (HttpRuntime)typeof(HttpRuntime).InvokeMember("_theRuntime",
                                     BindingFlags.NonPublic | BindingFlags.Static | BindingFlags.GetField, null, null, null);
            if (runtime == null)
                return;
            string shutDownMessage = (string)runtime.GetType().InvokeMember("_shutDownMessage",
                        BindingFlags.NonPublic | BindingFlags.Instance | BindingFlags.GetField, null, runtime, null);
            string shutDownStack = (string)runtime.GetType().InvokeMember("_shutDownStack",
                       BindingFlags.NonPublic | BindingFlags.Instance | BindingFlags.GetField, null, runtime, null);

            DebugUtils.Instance.Log("MvcApplicationEnd事件触发：" + shutDownMessage + shutDownStack, DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss fff"));
        }
        catch (Exception ex)
        {
            DebugUtils.Instance.Log("MvcApplicationEnd事件触发异常:" + ex.Message, DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss fff"));
        }

此时的网站日志文件中：

两个明显的请求处理停顿，刚好分别对应了上面的两次start事件

项目中遇到的问题

项目中使用log4net记录日志 ，配置文件如下：

<?xml version="1.0" encoding="utf-8" ?>
<log4net>
<appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender" >
	<file value="App_Data/Logs/Logs.txt" />
	<encoding value="utf-8" />
	<appendToFile value="true" />
	<rollingStyle value="Size" />
	<maxSizeRollBackups value="10" />
	<maximumFileSize value="10000KB" />
	<staticLogFileName value="true" />
	<layout type="log4net.Layout.PatternLayout">
	<conversionPattern value="%-5level %date [%-5.5thread] %-40.40logger - %message%newline" />
	</layout>
</appender>
<root>
	<appender-ref ref="RollingFileAppender" />
	<level value="DEBUG" />
</root>
</log4net>

Application_Start：

    protected override void Application_Start(object sender, EventArgs e)
    {
        Clock.Provider = ClockProviders.Utc;

        //Log4Net configuration
        AbpBootstrapper.IocManager.IocContainer
            .AddFacility<LoggingFacility>(f => f.UseAbpLog4Net()
                .WithConfig(Server.MapPath("log4net.config"))
            );


        base.Application_Start(sender, e);

        SingletonDependency<IOnlineUserManager>.Instance.ReloadWhenApplicationStart();
    }

在站点发布后，常常会在某次Application_End事件触发后，日志不再记录，而等过段时间后又会有新的日志出现（Application_Start的日志为起始）。

确实也是因为文件被占用。

解决log4net独占日志文件的问题以及 log4net的各种输出配置

http://logging.apache.org/log4net/release/config-examples.html

log4net系列(三)--详解RollingFileAppender

log4net的配置详解

Application_Start 中的 SingletonDependency<IOnlineUserManager>.Instance.ReloadWhenApplicationStart();这行代码为什么经常不生效。

因为有socket连接及轮询请求的存在，常常是start事件在end之前被触发，所以在end事件触发时保存用户session数据就不合适了，因为保存与读取 的执行顺序无法保障。