[ASP.NET MVC] 系統 Log 設計思維與客製化 Log 系統
在規劃設計一個系統功能時,除了完成商業邏輯業務需求之外,在系統設計階段,就要同時規劃好系統 Log 記錄方式。
系統 Log 能幫助軟體工程師在除錯時,快速找到問題原因。當需要檢視歷史執行過程時,Log 可以還原執行軌跡。
而今天要實作的是在 ASP.NET MVC 設計自己的 Log 系統,教學內容加入了我個人的設計概念,與主流的 Log 有些不同,有興趣的朋友可以多學一種方式。
Contents
自動化系統 Log 設計概念
當自行設計系統 Log 時,要善用系統架構的生命週期事件,在不同的生命週期內自動儲存和輸出必要的資訊,讓 Log 自動化執行。
例如在 Controller 執行前的生命週期事件,就先記錄使用者資訊,而在 Controller 結束時的生命週期事件,就自動輸出 Log 達到自動化運作。
Log 的設計關係到整個系統的架構,將相同的功能先抽離出來至相同的方法內,例如 WebAPI 呼叫、資料庫存取等功能,當執行方法時同時記錄重要的資訊,例如傳入參數或 SQL 語法等重要資訊。
在系統設計階段時,就要先佈署好 Log 的記錄方法,讓重要資訊自動化儲存,在開發階段就只要專心處理業務邏輯即可。
接下來就會實作 ASP.NET MVC 自動化 Log 功能。
建立專案
開啟 Visual Studio 2022,建立新專案為「ASP.NET Web 應用程式 (.NET Framework)」。
輸入專案名稱、位置之後,選擇「MVC」範本,就可以建立專案。
新增 Log 處理類別
建立一個新類別,將所有關於 Log 控制的屬性和方法放在這類別裡面。
我命名這類別名稱為 “LogUtil”。
在 LogUtil 類別裡面加入屬性:
1 2 3 |
long StartTimeTicks; //開始時間(毫秒) List<string> MessageContent = new List<string>();//訊息 int MethodLevel = 0; //呼叫方法順序 |
加入建構子:
1 2 3 4 5 6 7 |
public LogUtil(string FunctionName, string HostIP, string BrowserVersion) { this.StartTimeTicks = DateTime.Now.Ticks / 0x2710L;//開始時間(毫秒) // Log 表頭 this.MessageContent.Add("[執行時間:" + DateTime.Now.ToString("yyyy/MM/dd HH:mm:ss") + "] [執行程式:" + FunctionName + "] [來源 IP:" + HostIP + "] [瀏覽器版本:" + BrowserVersion + "]"); } |
初始化建構子的時候就開始建立 Log 內容了。
新增 Controller 底層類別
Controller 底層類別是讓專案內所有 Controller 繼承的,而此類別又繼承 Controller。
在此類別就可以覆寫 ASP.NET MVC 的生命週期事件,讓專案 Controller 在運行時,同步執行我們自訂的生命週期事件。
此類別我命名為 “ProjectBase”。
建立類別後,將此類別繼承 Controller。
覆寫 OnActionExecuting 事件
OnActionExecuting 事件是 MVC 執行 Action 呼叫前的事件,我們在此事件內建立我們的 LogUtil 物件,就可以開始記錄運行時的 Log 內容。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 |
public LogUtil logUtil = null; /// <summary> /// 在執行 Action 之前執行 /// </summary> /// <param name="filterContext"></param> protected override void OnActionExecuting(ActionExecutingContext filterContext) { // Log 初始化 string FunctionName = Request.CurrentExecutionFilePath; //執行程式 string HostIP = GetClientIP(); //呼叫來源主機 string BrowserVersion = this.GetClientBrowserVersion(); //瀏覽器版本 this.logUtil = new LogUtil(FunctionName, HostIP, BrowserVersion); // 取得輸入參數轉為 Json Hashtable param = new Hashtable(); // Post 參數 foreach (string key in base.Request.Form.Keys) { if (key == null) { continue; } if (key.StartsWith("__")) { continue; } param.Add(key, base.Request[key]); } // Get 參數 foreach (string key in base.Request.QueryString.Keys) { param.Add(key, base.Request.QueryString[key]); } string paramJson = JsonConvert.SerializeObject(param); if (paramJson.Length > 2) { this.logUtil.AppendMessage("傳入參數", paramJson); } // 登入者帳號 if (Session["UserID"] != null && Session["UserID"].ToString() != "") { this.logUtil.AppendMessage("登入帳號", Session["UserID"].ToString()); } base.OnActionExecuting(filterContext); } /// <summary> /// 取得遠端呼叫者ip /// </summary> /// <returns></returns> public string GetClientIP() { string ClientIP = ""; if (Request.ServerVariables["HTTP_VIA"] == null) { ClientIP = Request.ServerVariables["REMOTE_ADDR"].ToString(); } else { ClientIP = Request.ServerVariables["HTTP_X_FORWARDED_FOR"].ToString(); } ClientIP = ClientIP.Replace("::1", "127.0.0.1"); return ClientIP; } /// <summary> /// 取得遠端呼叫者瀏覽器版本 /// </summary> /// <returns></returns> public string GetClientBrowserVersion() { HttpBrowserCapabilitiesBase bc = Request.Browser; string brow_ver = bc.Browser + " " + bc.Version; return brow_ver; } |
LogUtil 類別被初始化時,就可以記錄初始資料了,包含執行程式、來源 IP 還有瀏覽器版本。
還有一個比較重要的是記錄來源的參數內容,我們分別從 Post 和 Get 來取得這些參數記錄下來,將來程式發生錯誤時,可以從參數裡面來找到可能錯誤的原因。
還有一個常見要記錄的是使用者身份,所以我從 Session 裡面判斷使用者身份,如果有的話,就一起記錄起來。
Log 記錄資料方法
LogUtil 完成建構子方法後,接下來可以新增方法來記錄資料。
這裡我提供 2 個方法範例,這是我個人常用的方法,給你們當作一種參考,你們可以自行變化這些方法。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 |
/// <summary> /// 記錄方法名稱 /// </summary> /// <param name="text"></param> public void AppendMethod(string text) { this.MethodLevel = this.MethodLevel + 1; this.MessageContent.Add(this.MethodLevel + ". " + text); } /// <summary> /// 記錄訊息內容 /// </summary> /// <param name="text"></param> public void AppendMessage(string tag, string text) { this.MessageContent.Add("[" + tag + "] " + text); } |
AppendMethod 是記錄正在執行的方法名稱,AppendMessage 是記錄內容。
Controller 呼叫方式
在 Controller 都需要先把 HomeController : Controller
改為 HomeController : ProjectBase
,才會執行我們的自定底層事件。
接下來我在 HomeController 裡面實作怎麼使用這些 LogUtil 方法。
基本使用方式:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 |
public ActionResult Index() { // 記錄方法名稱 this.logUtil.AppendMethod(MethodBase.GetCurrentMethod().DeclaringType.FullName + "." + MethodBase.GetCurrentMethod().Name); //呼叫資料庫 DataTable dt = this.CallDatabase(); // 回傳 Model Hashtable outModel = new Hashtable(); //測試 Model outModel.Add("Result", dt); return View(outModel); } /// <summary> /// 呼叫資料庫 /// </summary> private DataTable CallDatabase() { // 記錄方法名稱 this.logUtil.AppendMethod(MethodBase.GetCurrentMethod().DeclaringType.FullName + "." + MethodBase.GetCurrentMethod().Name); string connStr = System.Web.Configuration.WebConfigurationManager.ConnectionStrings["ConnDB"].ConnectionString; SqlConnection conn = new SqlConnection(); conn.ConnectionString = connStr; conn.Open(); string sql = "select UserName from Member where UserID = @UserID "; //測試用 sql SqlCommand cmd = new SqlCommand(); cmd.CommandText = sql; cmd.Connection = conn; cmd.Parameters.AddWithValue("@UserID", "Test"); // 在執行 SQL 之前先記錄指令 string sqlLog = sql; foreach (SqlParameter param in cmd.Parameters) { sqlLog = sqlLog.Replace(param.ParameterName.ToString(), "'" + param.Value.ToString() + "'"); } this.logUtil.AppendMessage("SQL", sqlLog); SqlDataAdapter adpt = new SqlDataAdapter(); adpt.SelectCommand = cmd; DataSet ds = new DataSet(); adpt.Fill(ds); DataTable dt = ds.Tables[0]; // 省略... conn.Close(); return dt; } |
語法 MethodBase.GetCurrentMethod().DeclaringType.FullName + "." + MethodBase.GetCurrentMethod().Name
會顯示目前正在執行的類別和方法名稱,可以放在所有方法的開頭,就可以記錄正在執行那一個方法了。
當執行的方法內會再呼叫其他的方法時,可以在每一個方法的開頭處記錄方法名稱。
假設遇到要呼叫別的專案的方法時,可以先把物件化的 logUtil 丟到其他的專案內,就可以記錄其他的專案的方法名稱,而最後的 Log 則會有方法呼叫的順序記錄。
這裡我示範向資料庫下 SQL 指令之前,先記錄到 Log 裡面再來執行指令,如果 SQL 指令發生錯誤的時候,我們可以從 Log 裡面找到指令來還原錯誤。
實務上執行 SQL 可以放在獨立的類別內,同樣將物件化的 logUtil 丟到類別內,當執行 SQL 指令時就可以記錄此一次的 Action 包含那些 SQL 指令。
有參數的範例
在 OnActionExecuting 裡面有記錄網頁傳入的參數,這裡就做一個示範,建立新 Action 傳入參數。
如果我們的 Action 有接收到參數,就會自動被記錄起來。
1 2 3 4 5 6 7 8 9 10 11 12 |
public ActionResult Divide(int x, int y) { // 記錄方法名稱 this.logUtil.AppendMethod(MethodBase.GetCurrentMethod().DeclaringType.FullName + "." + MethodBase.GetCurrentMethod().Name); int z = x / y; Hashtable outModel = new Hashtable(); outModel.Add("Result", z.ToString()); return View(outModel); } |
輸出 Log 記錄
記錄 Log 的目的是為了輸出,所以在 LogUtil 裡面增加一方法 OutputLog()
。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 |
/// <summary> /// 輸出 Log /// </summary> public void OutputLog() { string LogSaveType = ConfigurationManager.AppSettings["LogSaveType"]; //Log 儲存方式 string LogPath = ConfigurationManager.AppSettings["LogPath"]; //Log 檔案儲存路徑 // 執行時間 long runTimeMillisecond = (DateTime.Now.Ticks / 0x2710L) - this.StartTimeTicks; this.AppendMessage("執行時間", runTimeMillisecond.ToString("N0") + " ms"); string[] saveTypes = LogSaveType.Split(','); foreach (string type in saveTypes) { if (type == "HTML") { // 輸出為 HTML if (System.IO.Directory.Exists(LogPath) == false) { System.IO.Directory.CreateDirectory(LogPath); } string logFile = LogPath + DateTime.Now.ToString("yyyyMMdd") + ".htm"; //寫入檔案 StreamWriter writer = new StreamWriter(logFile, true, Encoding.GetEncoding("UTF-8")); foreach (string message in this.MessageContent) { writer.WriteLine(message.Replace("\n", "<br>") + "<br>"); } writer.WriteLine("<hr>"); writer.Flush(); writer.Close(); } if (type == "DB") { //輸出至資料庫 // 取得資料庫連線字串 string connStr = System.Web.Configuration.WebConfigurationManager.ConnectionStrings["ConnDB"].ConnectionString; // 當程式碼離開 using 區塊時,會自動關閉連接 using (SqlConnection conn = new SqlConnection(connStr)) { // 資料庫連線 conn.Open(); // 寫入 Log 資料表 string sql = @"INSERT INTO SystemLog(LogTime ,LogMessage) VALUES (@LogTime, @LogMessage)"; SqlCommand cmd = new SqlCommand(sql, conn); // 使用參數化填值 string errorContent = string.Join("\n", this.MessageContent.ToArray()); cmd.Parameters.AddWithValue("@LogTime", DateTime.Now.ToString("yyyy/MM/dd HH:mm:ss")); cmd.Parameters.AddWithValue("@LogMessage", errorContent); // 執行資料庫更新動作 cmd.ExecuteNonQuery(); } } } } |
可以在 Web.config 裡面儲存參數,設定的方法是。
1 2 |
<add key="LogSaveType" value="HTML,DB"/> <add key="LogPath" value="C:\temp\"/> |
輸出 Log 的方法,我這裡提供 HTML 和資料庫兩種範例,也可以兩種同時使用。
輸出的內容就是將 MessageContent 陣列物件裡面的資料輸出即可。
資料庫連線設定一樣在 Web.config 裡面設定,例如這樣:
1 2 3 |
<connectionStrings> <add name="ConnDB" connectionString="Data Source=127.0.0.1;Initial Catalog=Teach;Persist Security Info=false;User ID=test;Password=test;" providerName="System.Data.SqlClient" /> </connectionStrings> |
Log 資料表
這裡設計了一個資料表來儲存 Log 內容,Schema 如下:
1 2 3 4 5 |
CREATE TABLE [dbo].[SystemLog]( [LogTime] [datetime] NOT NULL, [LogMessage] [nvarchar](max) NOT NULL ) ON [PRIMARY] TEXTIMAGE_ON [PRIMARY] GO |
可以自行修改額外要儲存的欄位。
覆寫 OnResultExecuting 事件
OnResultExecuting 事件是 MVC 顯示畫面前的生命週期事件,此事件也排在 Action 執行結束之後,我們在此事件內自動輸出呼叫 Controller 的所有記錄內容。
如果回傳的內容有包含 Model 時,就將 Model 輸出至 Log。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 |
/// <summary> /// 在執行 Action Result 之前執行 /// </summary> /// <param name="filterContext"></param> protected override void OnResultExecuting(ResultExecutingContext filterContext) { // 自動記錄輸出 Model if (((System.Web.Mvc.ViewResultBase)filterContext.Result).Model != null) { this.logUtil.AppendMessage("輸出 Model", JsonConvert.SerializeObject(((System.Web.Mvc.ViewResultBase)filterContext.Result).Model)); } this.logUtil.OutputLog(); //輸出Log base.OnResultExecuting(filterContext); } |
測試結果
完成到這裡,我們就可以做初步的測試了,當程式執行之後,在 C:\Temp 就會出現執行日期的 Log 檔案。
打開之後就會記錄這一次 Controller 呼叫的 Log。
打開資料庫查看 SystemLog 資料表也會看到對應的 Log。
記錄錯誤訊息
在程式執行的過程中難免都會出錯,我們可以將錯誤訊息記錄下來,事後來找原因。
在 ProjectBase 類別裡面,繼續增加一個 MVC 事件 OnException()
來記錄錯誤 Log。
OnException()
是當後端程式發生錯誤時會進入的事件,我們可以在此取得完整 Exception 內容,再輸出至 Log。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 |
/// <summary> /// 錯誤事件 /// </summary> /// <param name="filterContext"></param> protected override void OnException(ExceptionContext filterContext) { //儲存錯誤訊息 StringBuilder buff = new StringBuilder(); buff.Append(string.Concat(new object[] { "Exception.Type : ", filterContext.Exception.GetType().Name, "\r\nException.Message : ", filterContext.Exception.Message, "\r\nException.TargetSite: ", filterContext.Exception.TargetSite, "\r\nException.StackTrace: \r\n", filterContext.Exception.StackTrace })); this.logUtil.AppendMessage("系統發生錯誤", buff.ToString()); //輸出 Log this.logUtil.OutputLog(); base.OnException(filterContext); } |
測試錯誤訊息
我們剛剛已經建立了 Divide(int x, int y)
的 Action,可以故意傳入會錯誤的參數。
按 F5 執行專案後,網址輸入 https://{網域}/Home/Divide?x=2&y=0
就會得到一個除以 0 的錯誤。
打開 Log 檔案後,同時也會記錄錯誤內容。
在資料庫的 SystemLog 裡面同時也會存有 Log 內容。
完整記錄 Exception Trace 會方便找到錯誤程式碼位置喔。
我的設計概念
關於 MVC 的 Log 機制,許多人都會使用 AOP (Aspect-Oriented Programming) 概念來實作,而我並沒有這樣做,主要是因為幾個原因。
- 我記錄 Log 希望可以記錄一整包的資訊,包含呼叫入口、使用者帳號、傳入參數、呼叫方法順序、執行 SQL 指令、輸出結果、執行時間、錯誤訊息等完整的資訊,當事後查詢時,可以瀏覽完整的執行過程。
- 獨立宣告 LogUtil 類別來記錄 Log 是因為此類別會獨立在專案類別庫裡面,而此 LogUtil 會由 ASP.NET MVC , ASP.NET Web Form, WinForm, Console 等專案來載入此類別庫來操作 LogUtil 類別,達到多個專案有統一的記錄方法。
- ASP.NET MVC 的 ActionFilter 無法達到物件傳遞共用的模式,所以放棄了在 ActionFilter 實作 Log,改由覆寫 Controller 的生命週期事件來實作。
好了,以上就是示範 ASP.NET MVC 系統自動化 Log 教學程式,可能這個方法與多數的 Log 方法不同,也無法實作 AOP 概念,但這是我一種設計方法,有需要的朋友就自行參考使用了。
範例下載
相關學習文章
如果你在學習上有不懂的地方,需要諮詢服務,可以參考站長服務,我想辨法解決你的問題
如果文章內容有過時、不適用或錯誤的地方,幫我在下方留言通知我一下,謝謝
1) mvc 本身就有actionfilter 可以實作,不用繞這麼一大圈
2) 你目前Log機制無法自訂Loglevel,實務上會打掛自已系統的
3) 你目前Log機制比起AOP的做法,無法自動實現在任一流程中自動Log,必須依靠developer使用你的Log物件,實在看不出來比起serilog等套件好用在哪
謝謝指教,我請教一下
我認為我的重點會放在 LogUtil 這個物件,他物件化之後,讓我方便在 Controller 內放到其他的處理元件上,例如資料庫元件上去呼叫
如果是使用 ActionFilterAttribute,這類別和 Controller 兩者沒有依相關係,我的物件無法直接繼承共用
ActionFilterAttribute 只能記錄Acion 和 Exception 的資訊,無法加入在 Contrller 想加入log 的內容
一個物件從頭傳遞到尾,架構面真的合適?
log trace 採用的是 trace id 來串起整個流程所有的log記錄
不會是弄一個log 物件然後傳來傳去的