測試項目搭建
定義一個簡單的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執行完畢才觸發。
待解決的疑問：
- 上面測試中情況
前面使用同一個日志文件時，日志只記錄部分，甚至很規律地交替出現，是因為文件被占用嗎?
在打開日志文件時刻意拋出異常，網站可以照常訪問，但不再記錄日志了，所以文件占用異常確實可以導致上述情況。
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
Application_Start 中的 SingletonDependency<IOnlineUserManager>.Instance.ReloadWhenApplicationStart();這行代碼為什么經常不生效。
因為有socket連接及輪詢請求的存在，常常是start事件在end之前被觸發，所以在end事件觸發時保存用戶session數據就不合適了，因為保存與讀取 的執行順序無法保障。