關於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數據就不合適了，由於保存與讀取 的執行順序沒法保障。