最近看到知乎上的一篇關(guān)于工業(yè)無(wú)人機(jī)的貼。里面有一句話(huà)觸動(dòng)了我：所有的無(wú)人機(jī)都在和我們說(shuō)續(xù)航說(shuō)載重硕蛹，但問(wèn)題是我們根本不關(guān)注這些醇疼，我們最關(guān)心的是能不能幫我們解決問(wèn)題。這句話(huà)完全可以成為一種模式法焰，所有的 XXX 都在說(shuō) XXX秧荆，但是它們不解決我的痛點(diǎn)。今天我們就說(shuō)一下 Log埃仪。

Log 工具很多很多乙濒，大的例如：Google Could Platform、Splunk卵蛉、Elmah.io……颁股，這些解決的是 Log Storage，Log Searching & Analyzing 以及 Dashboard傻丝。小的甘有，例如，log4X葡缰，NLog……亏掀，解決的是如何將日志寫(xiě)入介質(zhì)的問(wèn)題。但是這些工具沒(méi)有辦法告訴你泛释，你應(yīng)該在哪兒記錄 Log滤愕，記錄什么信息，最后一公里連不起來(lái)怜校。我們討論的焦點(diǎn)就在這里间影。

記 Log 似乎很簡(jiǎn)單，工具的接口也很統(tǒng)一茄茁。于是魂贬，我們看到了好多好多這樣的代碼：

logger.Error("Entity id is invalid.");

這種日志相關(guān)的代碼在功能 sign off 的時(shí)候或用戶(hù) acceptance test 的時(shí)候往往被忽略。但是好產(chǎn)品都是運(yùn)維出來(lái)的裙顽。你有沒(méi)有想過(guò)這樣的代碼會(huì)讓 Ops 瘋掉呢付燥？

好的，現(xiàn)在產(chǎn)品環(huán)境出現(xiàn)了一個(gè)問(wèn)題锦庸，Ops 接到了反饋后在日志中查到了 N 條這樣的日志

2016/02/02 22:22:22 Entity id is invalid.

你能想到他們的表情用一句話(huà)表示就是：大哥你逗我呢机蔗。表情結(jié)束后蒲祈，他們需要解決幾個(gè)問(wèn)題：

• 我怎么知道客戶(hù)遇到的問(wèn)題就是這種日志所描述問(wèn)題甘萧？
• 這種日志同一時(shí)間有好多我怎么知道哪一條是真正造成問(wèn)題的萝嘁？
• 出問(wèn)題的 Entity Id 長(zhǎng)什么樣？
• 我怎么知道這個(gè)問(wèn)題出現(xiàn)的時(shí)候客戶(hù)在干什么扬卷？
• 這個(gè)問(wèn)題的代碼在什么位置牙言？

OK，你看到痛點(diǎn)了么怪得？日志系統(tǒng)根本不是用日志工具記點(diǎn)東西就搞定了的咱枉，記錄只是最后一步。整個(gè)日志系統(tǒng)是需要根據(jù)運(yùn)維的需求進(jìn)行設(shè)計(jì)的徒恋。雖然運(yùn)維的需求有很多蚕断，例如，我想報(bào)告系統(tǒng)的問(wèn)題入挣，我想分析用戶(hù)的行為……但是總結(jié)起來(lái)就是記敘文的套路：誰(shuí)亿乳，什么時(shí)候，在什么地方径筏，干了什么葛假，造成了什么樣的后果。而翻譯成技術(shù)語(yǔ)言就是：

• 誰(shuí)：誰(shuí)調(diào)用了這個(gè) API滋恬；
• 什么時(shí)候：事情發(fā)生的統(tǒng)一時(shí)間聊训；
• 在什么地方：指代調(diào)用入口，往往調(diào)用入口代表了相應(yīng)的功能恢氯；
• 干了什么：以什么樣的參數(shù)執(zhí)行了什么過(guò)程带斑；
• 造成了什么樣的后果：應(yīng)當(dāng)如何評(píng)價(jià)這個(gè)日志？一般有 Information酿雪、Warning遏暴、Error 以及 Fatal。

接下來(lái)我們就從這些方面考慮日志到底怎么記指黎。我們的目標(biāo)是：如果我是運(yùn)維朋凉，面對(duì)這樣一條日志，我能夠知道這個(gè)日志從何而來(lái)醋安，我接下來(lái)應(yīng)該做什么杂彭？當(dāng)然從步驟上就是：

• 盡可能的收集信息；
• 把這些信息記下來(lái)吓揪。

簡(jiǎn)單吧亲怠。

開(kāi)始收集信息吧

我們剛才提到了日志包含信息。但是這些信息從何而來(lái)呢柠辞？

• 誰(shuí)：這個(gè)概念一般是系統(tǒng)的 Authentication 部分回答的团秽。至于 authorization 部分該不該包含，包含多少，則需要根據(jù)業(yè)務(wù)規(guī)則進(jìn)行分析了习勤，但是我更傾向于 authorization 是一個(gè)業(yè)務(wù)相關(guān)的東西踪栋，應(yīng)該放在 干了什么 里面。
• 什么時(shí)候：這個(gè)信息應(yīng)該是最容易獲得的了图毕。如果考慮 global 問(wèn)題則應(yīng)當(dāng)使用統(tǒng)一的標(biāo)準(zhǔn)夷都，例如，全部使用 UTC 日期時(shí)間予颤。
• 在什么地方：調(diào)用入口應(yīng)該是和業(yè)務(wù)無(wú)關(guān)的囤官。例如 request URI。
• 干了什么：這個(gè)應(yīng)當(dāng)是完全業(yè)務(wù)相關(guān)的部分蛤虐。只有在業(yè)務(wù)上下文下這些數(shù)據(jù)才有意義党饮。
• 造成了什么樣的后果：這種后果實(shí)際上可以通過(guò)以下問(wèn)題來(lái)區(qū)分：
  • Information：這不是一個(gè)錯(cuò)誤吧驳庭？我只是希望在“煩人”模式下獲得更多的調(diào)試信息劫谅。
  • Warning：這個(gè)問(wèn)題是由用戶(hù)的請(qǐng)求的數(shù)據(jù)造成的么捏检？或者這個(gè)問(wèn)題是我們事前就可以預(yù)料到的么？
  • Error：哎呀不皆，竟然發(fā)生了一個(gè)錯(cuò)誤贯城？@_@
  • Fatal：我知道這個(gè)錯(cuò)誤，但是一旦它發(fā)生了缀拭，我們就要完蛋了。

在開(kāi)始收集信息之前踩晶，我們應(yīng)該搞清楚我們的重點(diǎn)是和業(yè)務(wù)無(wú)關(guān)的部分渡蜻。因?yàn)樗堑湫偷幕?20% 的精力解決 80% 事情的部分茸苇，即使是不同的系統(tǒng)也有非常多的共性沦寂。這些部分我們可以從功能上將其內(nèi)聚起來(lái)，稱(chēng)之為 Logging Context传藏。

誰(shuí)

你猜 誰(shuí) 這個(gè)部分應(yīng)當(dāng)記些什么呢？姓名哭靖？年齡款青？出生年月霍狰？地址？約不約康震？別忘了宾濒，這個(gè)東西是干什么的——

查他/她！
--《黎明之前》

姓名年齡什么的都沒(méi)有用橘忱，因?yàn)榭梢灾孛梢酝晖峦丈斗睢Ｉ矸葑C？先別說(shuō)你搞得到搞不到國(guó)外的同學(xué)怎么辦凝颇？萬(wàn)一是一個(gè)虛擬角色（例如疹鳄，新浪調(diào)了我的服務(wù)）怎么辦瘪弓？因此你記錄的應(yīng)該是查到使用者的唯一標(biāo)識(shí)。那么這個(gè)標(biāo)識(shí)是什么呢腺怯？具體系統(tǒng)具體分析瓢喉，但是你在這兒放一個(gè)字符串就應(yīng)該已經(jīng)足夠了。

那么我什么時(shí)候取到這個(gè)信息呢决左？在 Authentication 過(guò)后就可以拿到。在很多 Web Service Framework 中都具有 pipeline 的概念惑芭，而 Authentication 往往位于這條 pipeline 的最前端继找，這樣只要我們將記錄 誰(shuí) 的操作放在其后就可以了。

范例

以 C# 為例幻锁。代碼很簡(jiǎn)單边臼，就是單純的 getter 和 setter柠并。例如：

public interface ILoggingContext {
    string Subject { get; set; }
    // ...
}

如果你使用的是 ASP.NET WebAPI，那么就可以將賦值操作放在 Message Handler 里面鸣戴，例如：

public class LoggingContextHandler : DelegatingHandler
{
    protected override Task<HttpResponseMessage> SendAsync(
        HttpRequestMessage request, 
        CancellationToken cancellationToken)
    {
        var context = (ILoggingContext)request
           .GetDependencyScope()
           .GetService(typeof(ILoggingContext));
        
        // ...
        context.Subject = GetIdentityFromRequest(request);
        // ...
        return base.SendAsync(request, cancellationToken);
    }
}

上述代碼中我們假定了一個(gè) ILoggingContext 實(shí)現(xiàn)的實(shí)例是 RequestScope 的粘拾。在大多數(shù)情況下這非常合適半哟。

什么時(shí)候

幾乎各個(gè)系統(tǒng)都有相應(yīng)的代表時(shí)刻的接口。因此這里只是提醒一下盡量的使用 UTC 時(shí)間以便可以在分布式系統(tǒng)中比較一致的進(jìn)行時(shí)間的標(biāo)記盯串。這并不需要什么特別的接口戒良。

在什么地方

對(duì)于這個(gè)信息，我們可以統(tǒng)一在入口處處理几缭。例如沃呢，對(duì)一個(gè) Web 應(yīng)用來(lái)說(shuō)薄霜，這個(gè)信息就是 Request 的 Uri纸兔。而我們可以在 web service pipeline 的任意位置得到這個(gè)信息否副。

范例

我們不妨將這個(gè)信息稱(chēng)為為 EntryPoint。也是一個(gè)非常簡(jiǎn)單的屬性：

public interface ILoggingContext {
    string EntryPoint { get; set; }
    // ...
}

仍然以 ASP.NET WebAPI 應(yīng)用為例洲拇，我們可以很容易在 MessageHandler 里面記錄這個(gè)信息赋续。 例如：

public class LoggingContextHandler : DelegatingHandler
{
    protected override Task<HttpResponseMessage> SendAsync(
        HttpRequestMessage request, 
        CancellationToken cancellationToken)
    {
        var context = (ILoggingContext)request
           .GetDependencyScope()
           .GetService(typeof(ILoggingContext));
        
        // ...
        context.EntryPoint = request.RequestUri.AbsoluteUri;
        // ...
        return base.SendAsync(request, cancellationToken);
    }
}

干了什么 + 造成了什么后果

這兩個(gè)部分的信息和業(yè)務(wù)是最相關(guān)的队腐，我們將其稱(chēng)之為 LoggingScenario柴淘。由于一個(gè)請(qǐng)求可能會(huì)執(zhí)行多個(gè)業(yè)務(wù)流程秘通，因此一個(gè)請(qǐng)求可以包含多個(gè) LoggingScenario。由于和業(yè)務(wù)相關(guān)第股，我們無(wú)法推測(cè)出它的具體內(nèi)容话原。但是我們卻可以確定它的形式。

對(duì)于 干了什么涉馅，包含兩個(gè)部分的信息黄虱。首先捻浦，我執(zhí)行了什么過(guò)程或者我將要執(zhí)行什么過(guò)程，稱(chēng)為 description昧识；第二盗扒，我執(zhí)行這個(gè)過(guò)程中使用了什么參數(shù)或配置形导，稱(chēng)為 parameters朵耕。而 造成的后果 就是一個(gè)簡(jiǎn)單的枚舉（level）淋叶。

范例

Logging Scenario 包含三部分信息。

[Serializable]
public class LoggingScenario
{
    public string Description { get; set; }
    public LoggingLevel Level { get; set; }
    public object Parameters { get; set; }
}

我們?cè)?ILoggingContext 中添加接口將 LoggingScenario 寫(xiě)入到日志文件中处嫌，這樣每一次的寫(xiě)入都包含了所有 Ops 友好的信息熏迹。

public interface ILoggingContext
{
    // ...
    void WriteScenario(LoggingScenario scenario);
}

其使用方法如下：

var scenario = new LoggingScenairo(
    "Update Permission",
    new {
        TargetUserId = targetUser.Id
    },
    LoggingLevel.Info);
    
loggingContext.WriteScenario(scenario);

為異常創(chuàng)建并還原 LoggingScenario

異常是日志的一大信息來(lái)源凝赛。一般的，我們需要在未處理異常出現(xiàn)的時(shí)候記錄日志捆昏。下面我們專(zhuān)門(mén)來(lái)討論一下如何從一個(gè)異常自動(dòng)創(chuàng)建 LoggingScenario骗卜。

未處理異常一般表示了一個(gè)我們事先沒(méi)有預(yù)判到的狀態(tài)左胞，這個(gè)異常可能是我們主動(dòng)拋出的焚刺，也可能是由其他的代碼產(chǎn)生的门烂。因此必須顧及這兩種情況。對(duì)于前者蔓姚，可以在異常上追加一些信息描述業(yè)務(wù)場(chǎng)景坡脐，這樣我們可以使用簡(jiǎn)短明確的日志準(zhǔn)確描述問(wèn)題房揭；而對(duì)于后者晌端，我們將盡可能多的記錄異常的信息咧纠，通過(guò) EntryPoint 結(jié)合詳細(xì)的異常調(diào)用棧定位問(wèn)題發(fā)生的場(chǎng)景泻骤。

在大部分的技術(shù)棧中，異逞菅鳎可以攜帶額外的信息趋惨。對(duì)于 .NET 而言器虾，可以將這些信息存儲(chǔ)在 Exception.Data 中。我們可以創(chuàng)建一個(gè)擴(kuò)展方法將 scenario 相關(guān)的信息追加到我們主動(dòng)拋出的異常中端姚。

public static T MarkScenario<T>(
    this T error,
    string scenarioName,
    object parameters,
    LoggingLevel level)
    where T : Exception
{
    IDictionary errorData = error.Data;
    if (errorData.IsReadOnly) { return error; }
    errorData[ExceptionScenarioKey] = 
        new LoggingScenario(scenarioName, parameters, level);
    return error;
}

為了使用的方便我們還可以創(chuàng)建諸如以下形式的重載：

public static T MarkAsInfo<T>(
    this T error,
    string scenarioName,
    object parameters = null) where T : Exception
{
    return MarkScenario(
        error, scenarioName, parameters, LoggingLevel.Info);
}

在異常向上傳播的過(guò)程中挤悉，可能會(huì)被其他的異常包裹装悲。因此我們只需要順著 InnerException 的鏈條遞歸上去就可以確定這個(gè)異常鏈?zhǔn)欠駥儆谝粋€(gè)已知的 logging scenario尚氛。如果一個(gè)異步過(guò)程產(chǎn)生了一個(gè) AggregateException 則我們需要處理多個(gè) InnerExceptions 鏈條阅嘶，并分別標(biāo)記為不同的 Logging Scenario。如果是已知的抡蛙，則我們將會(huì)采用這些已知的信息進(jìn)行日志記錄（而非記錄詳細(xì)的異常堆棧）魂迄，不但準(zhǔn)確，而且節(jié)省日志存儲(chǔ)空間熊昌。而如果是未知的，則我們會(huì)記錄所有的調(diào)用堆棧灭美，以便最大可能的記錄有用的信息选泻。

對(duì)于 Web 應(yīng)用程序页眯，我們還可以根據(jù)異常的類(lèi)型確定 Logging Level，即對(duì)于 HttpException傀顾、HttpResponseException 類(lèi)型的異常碌奉，如果其 Status Code 不代表一個(gè)錯(cuò)誤赐劣，則是 Information，如果 Status Code 是 4XX 客戶(hù)端錯(cuò)誤婉徘，則記錄為 Warning咐汞，否則記錄為 Error。

在大部分的技術(shù)棧下几晤，總有一個(gè)點(diǎn)可以集中處理未處理的異常蟹瘾。我們就可以在這一點(diǎn)從異常中創(chuàng)建 LoggingScenario掠手。并追加到 ILoggingContext 實(shí)例中。

把收集到的信息記錄下來(lái)吧

好了現(xiàn)在我們有了全知全能的 Logging Context伊脓。接下來(lái)的事情是都變得非常簡(jiǎn)單了呢。我們只要把所有信息拿出來(lái)一股腦的交給 Log4X 庫(kù)就好了株搔。很遺憾纤房，并非如此翻诉。請(qǐng)不要忘記以 Ops 的視角觀察問(wèn)題。

Ops 面對(duì)的是成山的 Log舒岸，因此芦圾，我們應(yīng)當(dāng)盡量令其易解析个少，可查詢(xún)（這里也要考慮 Log 分析工具的支持，例如 Splunk）壳澳。因此推薦使用 XML 或者 JSON 的方式進(jìn)行日志的存儲(chǔ)茫经。例如科平，我們可以創(chuàng)建一個(gè) ILogFormatter 用于格式化日志信息姜性，再創(chuàng)建一個(gè) ILogWriter 接口用于和不同的日志 library 進(jìn)行集成部念。

例如：

public interface ILogFormatter
{
    string Format(
        DateTime time,
        string subject,
        string entryPoint,
        string description,
        object parameters);
}

public interface ILogWriter
{
    void Write(string message, LoggingLevel level);
}

public void WriteScenario(LoggingScenario scenario)
{
    string message;

    try
    {
        message = m_formatter.Format(
            scenario.Time,
            Subject,
            EntryPoint,
            scenario.Description,
            scenario.Parameters);
    }
    catch (Exception error)
    {
        m_writer.Write($"An error occured while generate log message: {error}", LoggingLevel.Error);
        return;
    }

    m_writer.Write(message, scenario.Level);
}

詳細(xì)的代碼請(qǐng)參見(jiàn) 我的 Github Repository儡炼。

總結(jié)

總之，我們要做的工作就是連接日志工具和應(yīng)用程序的最后一公里距離榜贴。將最有用的信息：誰(shuí)妹田，什么時(shí)候鹃共，在什么地方霜浴，干了什么蓝纲，造成了什么后果記錄下來(lái)税迷。這樣 Ops 看到將是一篇篇格式明確，內(nèi)容充實(shí)类溢，業(yè)務(wù)相關(guān)的記敘文而不只是冗長(zhǎng)的堆棧信息了露懒。