阿里妹導(dǎo)讀

日志是系統(tǒng)中熵增最快的一個(gè)模塊，它承載了業(yè)務(wù)野蠻生長(zhǎng)過(guò)程中的所有副產(chǎn)品。本文介紹了一個(gè)日志治理案例，圍繞降本和提效兩大主題，取得一定成效，分享給所有渴望造物樂(lè)趣的同學(xué)。

前言

履約管理是一個(gè)面向物流商家的OMS工作臺(tái)，自從初代目把架子搭起來(lái)之后，就沒(méi)有繼續(xù)投入了，后來(lái)一直是合作伙伴同學(xué)在負(fù)責(zé)日常維護(hù)和需求支撐。經(jīng)過(guò)幾年的野蠻生長(zhǎng)，系統(tǒng)已經(jīng)雜草叢生，亂象百出。再后來(lái)，甚至一度成為一塊無(wú)主之地，走行業(yè)共建的方式來(lái)支持。對(duì)于一個(gè)不支持行業(yè)隔離的系統(tǒng)，行業(yè)共建意味這個(gè)系統(tǒng)將快速腐化。

兩年前我開(kāi)始接管履約管理，來(lái)到這片廣闊的蠻荒之地，正如所有那些渴望造物樂(lè)趣并且手里剛好有錘子鐮刀的人，我就像一匹脫韁的野馬，腦子里經(jīng)常會(huì)產(chǎn)生很多大膽且新奇的想法，希望借此把履約管理打造成一個(gè)完美的系統(tǒng)。只可惜真正能夠付諸實(shí)踐的少之又少，本篇就是為數(shù)不多得以落地，并且有相當(dāng)實(shí)用價(jià)值idea中的一個(gè)，整理出來(lái)分享給有需要的同學(xué)做參考。

日志亂象

日志是日常開(kāi)發(fā)中最有可能被忽視，最容易被濫用的一個(gè)模塊。被忽視是因?yàn)榇蛉罩緦?shí)在是一個(gè)再簡(jiǎn)單不過(guò)的事，前人設(shè)計(jì)好了一個(gè)logback.xml，后面只需要依樣畫(huà)葫蘆定義一個(gè)logger，隨手一個(gè)info調(diào)用就搞定，他甚至不確定這條日志能不能打出來(lái)，也不知道會(huì)打在哪個(gè)文件，反正先跑一次試試，不行就換error。被濫用是因?yàn)椴煌瑘?chǎng)景日志的格式內(nèi)容千差萬(wàn)別，或者說(shuō)日志打法太靈活，太隨意了，風(fēng)格太多樣化了，以至于幾乎每個(gè)人一言不合就要自己寫(xiě)一個(gè)LogUtil，我見(jiàn)過(guò)最夸張的，一個(gè)系統(tǒng)中用于打日志的工具類(lèi)，有二三十個(gè)之多，后人糾結(jié)該用哪個(gè)工具可能就要做半個(gè)小時(shí)的思想斗爭(zhēng)，完美詮釋了什么叫破窗效應(yīng)。
最好的學(xué)習(xí)方式就是通過(guò)反面教材吸取教訓(xùn)，下面我們列舉一些最常見(jiàn)的日志設(shè)計(jì)開(kāi)發(fā)過(guò)程中的問(wèn)題。

分類(lèi)之亂

一般來(lái)說(shuō)，一個(gè)系統(tǒng)必然需要設(shè)計(jì)多個(gè)日志文件以區(qū)分不同業(yè)務(wù)或場(chǎng)景，不可能所有的日志都打到一個(gè)文件里。但是怎么進(jìn)行分類(lèi)，沒(méi)人告訴我們，于是就有了各種各樣的分類(lèi)。

按系統(tǒng)模塊分。這種分類(lèi)應(yīng)該是最基礎(chǔ)的一種分類(lèi)，也是最有層次感的分類(lèi)。比如履約服務(wù)中樞的系統(tǒng)分層。基本上每一層對(duì)應(yīng)一個(gè)日志文件。

按租戶(hù)身份分。

一般中臺(tái)系統(tǒng)都會(huì)支持多個(gè)租戶(hù)(行業(yè))，每一個(gè)租戶(hù)單獨(dú)對(duì)應(yīng)一個(gè)日志文件。這種分類(lèi)一般不會(huì)單獨(dú)使用，除非你要做完全意義上的租戶(hù)隔離。


意識(shí)流分類(lèi)法。

不符合MECE法則，沒(méi)有清晰統(tǒng)一的分類(lèi)邏輯，按業(yè)務(wù)分，按系統(tǒng)模塊分，按接口能力分，按新老鏈路分，各種分法的影子都能看到，結(jié)果就是分出來(lái)幾十個(gè)文件，打日志的人根本就不知道這一行的日志會(huì)打進(jìn)哪個(gè)文件。
以上說(shuō)的各種分類(lèi)方式，都不是絕對(duì)純粹的，因?yàn)闊o(wú)論哪一種，無(wú)論一開(kāi)始設(shè)計(jì)的多么邊界清晰，隨著時(shí)間的推進(jìn)，最后都會(huì)演變?yōu)橐粋€(gè)大雜燴。

某人希望單獨(dú)監(jiān)控某個(gè)類(lèi)產(chǎn)生的日志，新增日志文件；

新增了一個(gè)業(yè)務(wù)，比如一盤(pán)貨，想單獨(dú)監(jiān)控，新增日志文件；

發(fā)起了一場(chǎng)服務(wù)化戰(zhàn)役，針對(duì)服務(wù)化鏈路單獨(dú)監(jiān)控，新增日志文件；

某個(gè)業(yè)務(wù)想采集用戶(hù)行為，又不想全接日志消息，新增日志文件；

資損敞口的場(chǎng)景，需要特別關(guān)注，新增日志文件；

特殊時(shí)期內(nèi)產(chǎn)生的日志，比如大促，新增日志文件；

凡此種種，不一而足。發(fā)現(xiàn)沒(méi)有，總有那么一瞬間能讓人產(chǎn)生新增日志文件的神經(jīng)沖動(dòng)，他們的訴求和場(chǎng)景也不可謂不合理，盡管這些日志的維度完全不相關(guān)，然而沒(méi)有什么能阻止這種沖動(dòng)。最開(kāi)始的那一套日志設(shè)計(jì)，就像一個(gè)瀕臨死亡的大象，不斷地被不同的利益方從身上扯下一塊分去。

格式之亂

對(duì)于日志需要有一定的格式這點(diǎn)相信沒(méi)有人會(huì)有異議，格式的亂象主要體現(xiàn)在兩個(gè)方面，一個(gè)是格式的設(shè)計(jì)上，有些系統(tǒng)設(shè)計(jì)了非常復(fù)雜的格式，用多種分隔符組合，支持日志內(nèi)容的分組，用關(guān)鍵詞定位的方式代替固定位置的格式，同時(shí)支持格式擴(kuò)展，這對(duì)人腦和計(jì)算機(jī)去解析都是一種負(fù)擔(dān)。第二個(gè)是同一個(gè)日志文件，還能出現(xiàn)不同格式的內(nèi)容，堆棧和正常業(yè)務(wù)日志混雜。


來(lái)看一個(gè)例子，我不給任何提示，你能在大腦里很快分析出這個(gè)日志的結(jié)構(gòu)嗎？

requestParam$&trace@2150435916867358634668899ebccf&scene@test&logTime@2023-06-14 17:44:23&+skuPromiseInfo$&itemId@1234567:1&skuId@8888:1&buyerId@777:1&itemTags@,123:1,2049:1,249:1,&sellerId@6294:1&toCode@371621:1&toTownCode@371621003:1&skuBizCode@TMALL_TAOBAO:1&skuSubBizCode@TMALL_DEFAULT:1&fromCode@DZ_001:1+orderCommonInfo$&orderId@4a04c79734652f6bd7a8876379399777&orderBizCode@TMALL_TAOBAO&orderSubBizCode@TMALL_DEFAULT&toCode@371621&toTownCode@371621003&+

工具之亂

有時(shí)候甚至?xí)霈F(xiàn)，同一個(gè)類(lèi)，同一個(gè)方法中，兩行不同的日志埋點(diǎn)，打出來(lái)的日志格式不一樣，落的日志文件也不一樣。為什么會(huì)出現(xiàn)這種情況？就是因?yàn)橛昧瞬煌娜罩竟ぞ摺Ｒ科涓?，我們需要分析一下不同的工具究竟是在做什么?？梢园l(fā)現(xiàn)，很多工具之間的差別就是支持的參數(shù)類(lèi)型不一樣，有些是打印訂單對(duì)象的，有些是打印消息的，有些是打印調(diào)度日志的。還有一些差別是面向不同業(yè)務(wù)場(chǎng)景的，比如一盤(pán)貨專(zhuān)用工具，負(fù)賣(mài)專(zhuān)用工具。還有一些差異是面向不同的異常封裝的，有些是打印ExceptionA，有些是打印ExceptionB的。人間離奇事，莫過(guò)于此，或許只能用存在即合理去解釋了。

日志分層

我一直信奉極簡(jiǎn)的設(shè)計(jì)原則，簡(jiǎn)單意味著牢不可破。上面提到，一套日志系統(tǒng)最終的結(jié)局一定是走向混亂，既然這種趨勢(shì)無(wú)法避免，那么我們?cè)谧畛踉O(shè)計(jì)的時(shí)候就只能確保一件事，保證原始的分類(lèi)盡量簡(jiǎn)單，且不重疊。其實(shí)通用的分類(lèi)方式無(wú)非就兩種，一種按職能水平拆分，一種按業(yè)務(wù)垂直拆分。一般來(lái)說(shuō)，一級(jí)分類(lèi)，應(yīng)該采用水平拆分。因?yàn)闃I(yè)務(wù)的邊界一般是很難劃清的，邊界相對(duì)模糊，職能的邊界就相對(duì)清晰穩(wěn)定很多，職能其實(shí)反映的是工作流，工作流一經(jīng)形成，基本不會(huì)產(chǎn)生太大的結(jié)構(gòu)性變化?；谶@種思路，我設(shè)計(jì)了如下的日志分層。
從層次上來(lái)看，其實(shí)只有三層，入口，內(nèi)核，出口。入口日志只負(fù)責(zé)打印流量入口的出入?yún)?，比如HSF，controller。出口日志負(fù)責(zé)打印所有第三方服務(wù)調(diào)用的出入?yún)?。?nèi)核日志，負(fù)責(zé)打印所有中間執(zhí)行過(guò)程中的業(yè)務(wù)日志。就三層足矣，足夠簡(jiǎn)單，不重不漏。另外把堆棧日志單獨(dú)拎出來(lái)，堆棧相比業(yè)務(wù)日志有很大的特殊性，本文標(biāo)題所指出的日志存儲(chǔ)降低優(yōu)化，也只是針對(duì)堆棧日志做的優(yōu)化，這個(gè)后面再講。

格式設(shè)計(jì)

日志的格式設(shè)計(jì)也有一些講究。首先日志的設(shè)計(jì)是面向人可讀的，這個(gè)無(wú)需多言。另外也非常重要的一個(gè)點(diǎn)，要面向可監(jiān)控的設(shè)計(jì)，這是容易被很多人忽視的一個(gè)點(diǎn)。基于這兩個(gè)原則，說(shuō)一下我在格式設(shè)計(jì)上的一些思路。


首先要做維度抽象。既然是面向監(jiān)控，監(jiān)控一般需要支持多個(gè)維護(hù)，比如行業(yè)維度，服務(wù)維度，商家維度等等，那么我們就需要把所有的維度因子抽出來(lái)。那么這些維度實(shí)際打印的時(shí)候怎么傳給logger呢？建議是把他們存到ThreadLocal中，打的時(shí)候從上下文中取。這樣做還有一個(gè)好處是，日志打印工具設(shè)計(jì)的時(shí)候就會(huì)很優(yōu)雅，只需要傳很少的參數(shù)。


格式盡量簡(jiǎn)單，采用約定大于配置的原則，每一個(gè)維度占據(jù)一個(gè)固定的位置，用逗號(hào)分割。切忌設(shè)計(jì)一個(gè)大而全的模型，然后直接整個(gè)的序列化為一個(gè)JSON字符串。


也不要被所謂的擴(kuò)展性給誘惑，給使用方輕易開(kāi)出一個(gè)能夠自定義格式的口子，即便你能輕而易舉的提供這種能力。根據(jù)我的經(jīng)驗(yàn)，這種擴(kuò)展性一定會(huì)被濫用，到最后連設(shè)計(jì)者也不知道實(shí)際的格式究竟是怎樣的。當(dāng)然這個(gè)需要設(shè)計(jì)者有較高的視野和遠(yuǎn)見(jiàn)，不過(guò)這不是難點(diǎn)，難的還是克制自己炫技的欲望。

在內(nèi)容上，盡量打印可以自解釋的文本，做到見(jiàn)名知義。舉個(gè)例子，我們要打印退款標(biāo)，退款標(biāo)原本是用1, 2, 4, 8這種二進(jìn)制位存儲(chǔ)的，打印的時(shí)候不要直接打印存儲(chǔ)值，翻譯成一個(gè)能描述它含義的英文code。 格式示例

timeStamp|threadName logLevel loggerName|sourceAppName,flowId,traceId,sceneCode,identityCode,loginUserId,scpCode,rpcId,isYace,ip||businessCode,isSuccess||parameters||returnResult||

2023-08-14 14:37:12.919|http-nio-7001-exec-10 INFO c.a.u.m.s.a.LogAspect|default,c04e4b7ccc2a421995308b3b33503dda,0bb6d59616183822328322237e84cc,queryOrderStatus,XIAODIAN,5000000000014,123456,0.1.1.8,null,255.255.255.255||queryOrderStatus,success||{"@type":"com.alibaba.common.model.queryorder.req.QueryOrderListReq","currentUserDTO":{"bizGroup":888,"shopIdList":[123456],"supplierIdList":[1234,100000000001,100000000002,100000000004]},"extendFields":{"@type":"java.util.HashMap"},"invokeInfoDTO":{"appName":"uop-portal","operatorId":"1110","operatorName":"account_ANXRKY8NfqFjXvQ"},"orderQueryDTO":{"extendFields":{"@type":"java.util.HashMap"},"logisTypeList":[0,1],"pageSize":20,"pageStart":1},"routeRuleParam":{"@type":"java.util.HashMap","bizGroup":199000},"rule":{"$ref":"$.routeRuleParam"}}||{"@type":"com.alibaba.common.model.ResultDTO","idempotent":false,"needRetry":false,"result":{"@type":"com.alibaba.common.model.queryorderstatus.QueryOrderStatusResp","extendFields":{"@type":"java.util.HashMap"}},"success":true}||

堆棧倒打

本文的重點(diǎn)來(lái)啦，這個(gè)設(shè)計(jì)就是開(kāi)頭提到的奇思妙想。堆棧倒打源于我在排查另一個(gè)系統(tǒng)問(wèn)題過(guò)程中感受到的幾個(gè)痛點(diǎn)，首先來(lái)看一個(gè)堆棧示例。
這么長(zhǎng)的堆棧，這密密麻麻的字母，即使是天天跟它打交道的開(kāi)發(fā)，相信第一眼看上去也會(huì)頭皮發(fā)麻?；叵胍幌挛覀兛炊褩?，真正想得到的是什么信息。



所以我感受到的痛點(diǎn)核心有兩個(gè)。第一個(gè)是，SLS(阿里云日志產(chǎn)品系統(tǒng))上搜出來(lái)的日志，默認(rèn)是折疊的。對(duì)于堆棧，我們應(yīng)該都知道，傳統(tǒng)異常堆棧的特征是，最頂層的異常，是最接近流量入口的異常，這種異常我們一般情況下不太關(guān)心。最底層的異常，才是引起系列錯(cuò)誤的源頭，我們?nèi)粘Ｅ挪閱?wèn)題的時(shí)候，往往最關(guān)心的是錯(cuò)誤源頭。所以對(duì)于堆棧日志，我們無(wú)法通過(guò)摘要一眼看出問(wèn)題出在哪行代碼，必須點(diǎn)開(kāi)，拉到最下面，看最后一個(gè)堆棧才能確定源頭。



我寫(xiě)了一個(gè)錯(cuò)誤示例來(lái)說(shuō)明這個(gè)問(wèn)題。常規(guī)的堆棧結(jié)構(gòu)其實(shí)分兩部分，我稱(chēng)之為，異常原因棧，和錯(cuò)誤堆棧。




如上，一個(gè)堆棧包含有三組異常，每一個(gè)RuntimeException是一個(gè)異常，這三個(gè)異常連起來(lái)，我們稱(chēng)為一個(gè)異常原因棧。


每一個(gè)RuntimeException內(nèi)部的堆棧，我們稱(chēng)為錯(cuò)誤堆棧。


說(shuō)明一下，這兩個(gè)名詞是我杜撰的，沒(méi)有看到有人對(duì)二者做區(qū)分，我們一般都統(tǒng)稱(chēng)為堆棧。讀者能理解我想表達(dá)的就行，不用太糾結(jié)名詞。


第二個(gè)痛點(diǎn)是，這種堆棧存儲(chǔ)成本太高，有效信息承載率很低。老實(shí)說(shuō)這一點(diǎn)可能大多數(shù)一線開(kāi)發(fā)并沒(méi)有太強(qiáng)烈的體感，但在這個(gè)降本增效的大環(huán)境下，我們每個(gè)人應(yīng)該把這點(diǎn)作為自己的OKR去踐行，變被動(dòng)為主動(dòng)，否則在機(jī)器成本和人力成本之間，公司只好做選擇題了。


現(xiàn)在目標(biāo)很明確了，那我們就開(kāi)始對(duì)癥下藥。核心思路有兩個(gè)。


針對(duì)堆棧折疊的問(wèn)題，采用堆棧倒打。倒打之后，最底層的異常放在了最上面，甚至不用點(diǎn)開(kāi)，瞟一眼就能知道原因。
同時(shí)我們也支持異常原因棧層數(shù)配置化，以及錯(cuò)誤堆棧的層數(shù)配置化。解這個(gè)問(wèn)題，本質(zhì)上就是這樣一個(gè)簡(jiǎn)單的算法題：倒序打印堆棧的最后N個(gè)元素。核心代碼如下。

/**
 * 遞歸逆向打印堆棧及cause(即從最底層的異常開(kāi)始往上打)
 * @param t 原始異常
 * @param causeDepth 需要遞歸打印的cause的最大深度
 * @param counter 當(dāng)前打印的cause的深度計(jì)數(shù)器(這里必須用引用類(lèi)型，如果用基本數(shù)據(jù)類(lèi)型，你對(duì)計(jì)數(shù)器的修改只能對(duì)當(dāng)前棧幀可見(jiàn)，但是這個(gè)計(jì)數(shù)器，又必須在所有棧幀中可見(jiàn)，所以只能用引用類(lèi)型)
 * @param stackDepth 每一個(gè)異常棧的打印深度
 * @param sb 字符串構(gòu)造器
 */
public static void recursiveReversePrintStackCause(Throwable t, int causeDepth, ForwardCounter counter, int stackDepth, StringBuilder sb){
    if(t == null){
        return;
    }
    if (t.getCause() != null){
        recursiveReversePrintStackCause(t.getCause(), causeDepth, counter, stackDepth, sb);
    }
    if(counter.i++ < causeDepth){
        doPrintStack(t, stackDepth, sb);
    }
}

要降低存儲(chǔ)成本，同時(shí)也要確保信息不失真，我們考慮對(duì)堆棧行下手，把全限定類(lèi)名簡(jiǎn)化為類(lèi)名全打，包路徑只打第一個(gè)字母，行號(hào)保留。如：c.a.u.m.s.LogAspect#log:88。核心代碼如下。

public static void doPrintStack(Throwable t, int stackDepth, StringBuilder sb){
    StackTraceElement[] stackTraceElements = t.getStackTrace();
    if(sb.lastIndexOf("	") > -1){
        sb.deleteCharAt(sb.length()-1);
        sb.append("Caused: ");
    }
    sb.append(t.getClass().getName()).append(": ").append(t.getMessage()).append("
	");
    for(int i=0; i < stackDepth; ++i){
        if(i >= stackTraceElements.length){
            break;
        }
        StackTraceElement element = stackTraceElements[i];
        sb.append(reduceClassName(element.getClassName()))
          .append("#")
          .append(element.getMethodName())
          .append(":")
          .append(element.getLineNumber())
          .append("
	");
    }
}

最終的效果大概長(zhǎng)這樣。我們隨機(jī)挑了一個(gè)堆棧做對(duì)比，統(tǒng)計(jì)字符數(shù)量，在同等信息量的情況下，壓縮比達(dá)到88%。

思維拓展

很多文章喜歡鼓吹所謂的最佳實(shí)踐，在筆者看來(lái)最佳實(shí)踐是個(gè)偽命題。當(dāng)你在談最佳實(shí)踐的時(shí)候，你需要指明這個(gè)"最"是跟誰(shuí)比出來(lái)的，你的適用范圍是哪些，我相信沒(méi)有任何一個(gè)人敢大言不慚自己的框架或方案是放之四海而皆準(zhǔn)的。


本文所提出的日志設(shè)計(jì)實(shí)踐方案，是在一個(gè)典型的中臺(tái)應(yīng)用中落地的，三段的日志分層方案雖然足夠簡(jiǎn)單，足夠通用，但是最近解觸了一些富客戶(hù)端應(yīng)用，這個(gè)方案要想遷移，可能就得做一些本土化的改造了。他們的特點(diǎn)是依賴(lài)的三方服務(wù)少，大量的采用緩存設(shè)計(jì)，這種設(shè)計(jì)的底層邏輯是，盡量使得所有邏輯能在本地客戶(hù)端執(zhí)行以降低分布式帶來(lái)的風(fēng)險(xiǎn)和成本，這意味著，可能99%的日志都是內(nèi)部執(zhí)行邏輯打的，那我們就得考慮從另一些維度去做拆分。另外對(duì)于日志降本，本文探討的也只是降堆棧的存儲(chǔ)，一個(gè)系統(tǒng)不可能所有日志都是堆棧，所以實(shí)際整體的日志存儲(chǔ)成本，可能降幅不會(huì)有這么多。

談這么多，歸根結(jié)底還是一句話，不要迷信銀彈，減肥藥一類(lèi)的東西，所有的技術(shù)也好，思想也好，都要量體裁衣，量力而行。


審核編輯：湯梓紅