NLog問題偵錯技巧

NLog是我們開發團隊的奧林匹克指定Log元件,但經驗裡遇過不少次沒有寫Log檔的狀況,而NLog為了避免寫Log過程出錯導致主程序中斷,預設不會拋出錯誤訊息,這讓NLog茶包特別難找。過去較常見問題是對Log資料夾缺少寫入權限(尤其是IIS 7.5+會用IIS APPPOOL\XXXX虛擬帳號,需要額外開權限),補設權限後就OK,對NLog問題如何除錯也未多深究。不料前幾天踢到鐵板,足足卡了一小時找出原因(代表以前是假會,只要不是權限問題就卡關,嗚~),不過因此學會NLog異常排除技巧是意外收獲。

NLog預設會忽略所有發生的錯誤(包含NLog.config壞掉都假裝沒事)以免干擾主程式執行,當需要偵錯時,NLog.config有個開關:<nlog throwExceptions="true" />,開啟後便知NLog為什麼沒成功寫入Log。

來個測試,故意移除Log資料夾寫入權限,並加上throwExceptions="true",錯誤訊息與爆炸程式行數一目瞭然:

除了設定NLog在出錯時直接拋出錯誤,還有另一種有效蒐集錯誤訊息的做法:<nlog internalLogLevel="Debug" internalLogFile="c:\temp\nlog-internal.log">,透過internalLogLevel及internalLogFile開啟NLog的內部Log,從中也可找出NLog無法寫入Log的原因(如下圖)。與throwExceptions="true"有以下不同:

  1. internalLogFile錯誤訊息的StackTracce資訊從NLog元件內部開始(在下例為NLog.Tragets.Target.Write),追不到logger.Debug()等寫入Log的程式來源。
  2. 若internalLogFile路徑遇上無權寫入,一樣暴斃驗無傷。
  3. internalLogFile不只可以記錯誤訊息,當internalLogLevel設成Debug、Trace等模式,還能看到更多NLog運作資訊。

同場加映一則小技巧-如何快速找出Target f的檔案路徑?結合先前介紹過的取得NLog檔案路徑以及在IIS主機現場撰寫測試ASPX偵錯,以下程式顯示LoggerName為"AAA"時的Log路徑,並試寫一個Debug Log,第一行NLog.LogManager.ThrowExceptions = true 可取代 <nlog throwExceptions="true">設定,在NLog出錯時顯示錯誤訊息。透過此一測試可以確認Log檔案位置以及寫入權限。

<%@ Page Language="C#" %> 
<% 
NLog.LogManager.ThrowExceptions = true; 
Response.Write( 
(NLog.LogManager.Configuration.FindTargetByName("f") as NLog.Targets.FileTarget).FileName 
.Render(new NLog.LogEventInfo() { TimeStamp = DateTime.Now, LoggerName = "AAA" }) 
); 
NLog.LogManager.GetLogger("AAA").Debug("TEST"); 
NLog.LogManager.Flush(); 
%>

還有一點,NLog.config在修改後,需要重啟Web Application才會生效,有個<nlog autoReload="true">可在NLog.config修改時自動載入,可在不中斷ASP.NET或Windows程序調整NLog設定。

【結論】

  1. NLog預設會壓抑所有NLog錯誤以免中斷主要程式邏輯,設定<nlog throwExceptions="true">可顯示NLog錯誤。
    提醒:問題排除後建議改回false,或用在測試程式中以NLog.LogManager.ThrowExceptions=true替代。
  2. 遇到NLog問題時,可寫一個迷你NLogTester.aspx檢查路徑及寫入權限。(範例請見文章)
  3. <nlog autoReload="true">可設定NLog.config修改後自動更新設定,省去重啟程序的困擾。

【延伸閱讀】

  1. Configuration file · NLog-NLog Wiki · GitHub
  2. Logging Troubleshooting · NLog-NLog Wiki · GitHub

【後記】

我這次遇到的狀況是程式換版,將已平測一段時間的新版資料夾取名取代舊版(包含NLog.config),後來想到要沿用原本NLog.config指定的Log路徑,再把舊版的NLog.config覆寫回去,從此再也沒看到有Log寫入。該Log路徑在換版前原本就運作良好,不該是權限問題,讓過去只會處理NLog DLL版本衝突跟Log目錄權限茶包的我黔驢技窮,瞎試半天無解,爬文學會開啟throwExceptions才水落石出:

Exception Details: System.IO.FileNotFoundException: Could not load file or assembly 'NLog.Targets.Syslog' or one of its dependencies. The system cannot find the file specified.

舊版的NLog.config設定了Syslog Target,如下例:

<?xml version="1.0" encoding="utf-8" ?> 
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" 
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"> 
  <extensions> 
    <add assembly="NLog.Targets.Syslog" /> 
  </extensions>    
  <targets> 
    <target xsi:type="File" name="f" fileName="D:/Log/${logger}/${shortdate}.log" 
            layout="${longdate} ${uppercase:${level}} ${message}" encoding="utf-8"/> 
    <target name="syslog" type="Syslog" syslogserver="syslog-server-ip" 
            port="514" facility="Local7" 
            sender="BLAH.UAT" layout="${longdate} ${uppercase:${level}} ${message}"/>            
  </targets> 
  <rules> 
    <logger name="*" minlevel="Trace" writeTo="f,syslog" /> 
  </rules> 
</nlog>

extensions引用了NLog.Targets.Syslog,舊版bin下有NLog.Targets.Syslog.dll,忘了複製到新版bin目錄導致錯誤,補上後問題排除。

歡迎推文分享:
Published 16 May 2016 12:00 AM 由 Jeffrey
Filed under: ,
Views: 3,638



意見

沒有意見

你的看法呢?

(必要的) 
(必要的) 
(選擇性的)
(必要的) 
(提醒: 因快取機制,您的留言幾分鐘後才會顯示在網站,請耐心稍候)

5 + 3 =

搜尋

Go

<May 2016>
SunMonTueWedThuFriSat
24252627282930
1234567
891011121314
15161718192021
22232425262728
2930311234
 
RSS
創用 CC 授權條款
【廣告】
twMVC

Tags 分類檢視
關於作者

一個醉心技術又酷愛分享的Coding魔人,十年的IT職場生涯,寫過系統、管過專案, 也帶過團隊,最後還是無怨無悔地選擇了技術鑽研這條路,近年來則以做一個"有為的中年人"自許。

文章典藏
其他功能

這個部落格


Syndication