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

Log 工具很多很多，大的例如：Google Could Platform、Splunk、Elmah.io……，這些解決的是 Log Storage，Log Searching & Analyzing 以及 Dashboard。小的，例如，log4X，NLog……，解決的是如何將日志寫入介質(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í)候或用戶 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.

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

• 我怎么知道客戶遇到的問(wèn)題就是這種日志所描述問(wèn)題？
• 這種日志同一時(shí)間有好多我怎么知道哪一條是真正造成問(wèn)題的？
• 出問(wèn)題的 Entity Id 長(zhǎng)什么樣？
• 我怎么知道這個(gè)問(wèn)題出現(xiàn)的時(shí)候客戶在干什么？
• 這個(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)題，我想分析用戶的行為……但是總結(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)單吧。

開始收集信息吧

我們剛才提到了日志包含信息。但是這些信息從何而來(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)題是由用戶的請(qǐng)求的數(shù)據(jù)造成的么？或者這個(gè)問(wèn)題是我們事前就可以預(yù)料到的么？
  • Error：哎呀，竟然發(fā)生了一個(gè)錯(cuò)誤？@_@
  • Fatal：我知道這個(gè)錯(cuò)誤，但是一旦它發(fā)生了，我們就要完蛋了。

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

誰(shuí)

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

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

姓名年齡什么的都沒(méi)有用，因?yàn)榭梢灾孛梢酝晖峦丈?。身份證？先別說(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è)信息稱為為 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)的，我們將其稱之為 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ò)程，稱為 description；第二，我執(zhí)行這個(gè)過(guò)程中使用了什么參數(shù)或配置，稱為 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 寫入到日志文件中，這樣每一次的寫入都包含了所有 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í)候記錄日志。下面我們專門來(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ù)棧中，異?？梢詳y帶額外的信息。對(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ù)異常的類型確定 Logging Level，即對(duì)于 HttpException、HttpResponseException 類型的異常，如果其 Status Code 不代表一個(gè)錯(cuò)誤，則是 Information，如果 Status Code 是 4XX 客戶端錯(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)盡量令其易解析，可查詢（這里也要考慮 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)的堆棧信息了。