轉：Logging 日誌記錄最佳實務

文章目錄

• 介紹
• 不同的日誌含義
• 為什麼要做日誌
• 一些日誌執行個體
• 要記錄的重要事件
• 哪些內容無需記錄
• 日誌記錄後該幹什嗎？
• 異常處理
• 處理 PHP 錯誤
• 不同的訊息層級以及什麼時候該用
• 聰明的日誌實現
• 結論

http://www.oschina.net/question/12_44624http://www.oschina.net/question/12_44624介紹

本文解釋應用程式中的錯誤和調試日誌的最佳實務。應用日誌是一個非常重要的“工具”用來幫你查明具問題。如果有一個基礎架構用來記錄應用中的日誌和事件，那麼調試和問題的解決就會變得很簡單。

在開始文章之前，我們要介紹兩個相關的工具：

• Logstash - http://www.oschina.net/p/logstash
• Graylog2 - http://www.oschina.net/p/graylog2

 

不同的日誌含義

日誌 Logging 可以代表不同的含義，有著不同的目的，在這篇文章中主要指應用程式的日誌。

應用日誌，或者也叫做調試資訊和錯誤記錄檔，主要的目的是為了跟蹤應用程式的底層行為，跟蹤應用內部所執行的過程。還有另外一些日誌，例如是 Google 的 Analytics 是用來統計網站的訪問量等資訊，這二者的目的是決然不同的。

為什麼要做日誌審計跟蹤

但錯誤發生時，你需要清除知道該如何處理，通過對日誌跟蹤，你可以擷取該錯誤發生的具體環境，你需要確切知道什麼是什麼引起該錯誤，什麼對該錯誤不會造成影響。

跟蹤應用的警告和錯誤

為了識別錯誤，我們將日誌分為警告和錯誤資訊，這些都是可以跟蹤並予以解決的。例如在 PHP 中 deprecated、strict 和 notices 類別的資訊是需要引起注意的。

跟蹤崩潰bug

在開發過程中，日誌可以協助開發人員和軟體測試人員跟蹤程式崩潰的原因。

跟蹤效能下降的問題範圍

產品所反映出來的效能問題，很難在開發過程中暴露出來，這需要進行全方位的測試跟蹤，而通過日誌提供的詳細執行時間記錄可以很方便的找出應用的效能瓶頸。

一些日誌執行個體

日誌的內容和格式並沒有人做嚴格的規定，但下面是我們給出的一些建議以供參考：

• 日誌發生的日期和時間，包含時區資訊和毫秒，建議使用 ISO-8601 時間格式
• 記錄層級，例如 debug、info 和 error
• 相應的會話標識，能知道是哪個用戶端或者是其他請求所產生的日誌，例如在 Web 日誌中 IP 位址就可以用來標識一個用戶端
• 一個有用的日誌內容

下面是一個好日誌的例子

[2012-03-02T20:20:49.003+01:00][43gg84][info] Bootstrapping application (v 2.1b)

 

這條日誌中包含：

1. 日期、時間，提供毫秒資訊和時區
2. 會話標識 43gg84，不同的用戶端會有不同的值
3. 記錄層級，在這裡是 info
4. 日誌詳情：Bootstrapping application

通過這條日誌我們就可以知道應用程式在什麼時候啟動了，這是一個非常重要的時間點。 

下面是一個不好的日誌例子，光知道錯誤，不知道發生什麼錯誤：

[Thu, 01 Jan 1970 00:00:00 +0100] Error: ""

(這是我在實際中遇見過的日誌，真實的問題是 Beanstalkd 伺服器沒啟動導致的，但這個錯誤資訊中完全沒有提及。)

一旦發生錯誤，使用堆棧的跟蹤是非常有用的，當然這也是一個巨大的開銷，因此要謹慎使用，到處拋出異常並不是一個好主意。

一個成功啟動過程的日誌資訊

讓我們繼續看一些好的例子，下面日誌包含了應用程式啟動完整過程：

[2012-03-02T20:20:49.003+02:00][43gg84][info] Bootstrapping application (v 2.1b)[2012-03-02T20:20:49.013+02:00][43gg84][info] Request cycle startup[2012-03-02T20:20:49.093+02:00][43gg84][info] User session found, user ID: 13414564[2012-03-02T20:20:49.123+02:00][43gg84][info] Requested URI '/fu/bar/index'[2012-03-02T20:20:49.133+02:00][43gg84][info] Requested forwarded to URI '/fu/bar/overview'[2012-03-02T20:20:49.273+02:00][43gg84][info] Sending HTTP headers[2012-03-02T20:20:49.283+02:00][43gg84][info] Sending HTTP Body[2012-03-02T20:20:49.313+02:00][43gg84][info] Request cycle shutdown[2012-03-02T20:20:49.323+02:00][43gg84][info] Request cycle completed in 0.320 seconds.

這個日誌自我解釋的非常清楚，你能知道當前應用的版本，URI 處理等詳細資料。

一個包含堆棧資訊的日誌

下面例子展示了如何輸出日誌堆棧，你可以看到堆棧資訊的層級和錯誤資訊是不同的，當然這不是固定的，有時候發生錯誤的時候，你需要記錄詳細的錯誤堆棧資訊以便跟蹤錯誤發生的具體位置：

[2012-03-02T20:20:49.003+02:00][43gg84][info] Bootstrapping application (v 2.1b)[2012-03-02T20:20:49.013+02:00][43gg84][info] Request cycle startup[2012-03-02T20:20:49.123+02:00][43gg84][info] Requested URI '/fu/bar/index'[2012-03-02T20:20:49.273+02:00][43gg84][info] Sending HTTP headers[2012-03-02T20:20:49.283+02:00][43gg84][erro] Cannot modify header information – headers already sent by X on line Y[2012-03-02T20:20:49.293+02:00][43gg84][dbug] Stack trace:[2012-03-02T20:20:49.293+02:00][43gg84][dbug]   1. {main}() /tmp/fu/bar/httpdocs/index.php:0[2012-03-02T20:20:49.293+02:00][43gg84][dbug]   2. Zend_Application->run() /tmp/fu/bar/httpdocs/index.php:31[2012-03-02T20:20:49.293+02:00][43gg84][dbug]   3. Zend_Application_Bootstrap_Bootstrap->run() /tmp/fu/bar/library/Zend/Application.php:366[2012-03-02T20:20:49.293+02:00][43gg84][dbug]   4. Zend_Controller_Front->dispatch() /tmp/fu/bar/library/Zend/Application/Bootstrap/Bootstrap.php:97[2012-03-02T20:20:49.293+02:00][43gg84][dbug]   5. Zend_Controller_Dispatcher_Standard->dispatch() /tmp/fu/bar/library/Zend/Controller/Front.php:954[2012-03-02T20:20:49.293+02:00][43gg84][dbug]   6. Zend_Controller_Action->dispatch() /tmp/fu/bar/library/Zend/Controller/Dispatcher/Standard.php:295[2012-03-02T20:20:49.293+02:00][43gg84][dbug]   7. IndexController->indexAction() /tmp/fu/bar/library/Zend/Controller/Action.php:513[2012-03-02T20:20:49.313+02:00][43gg84][info] Sending HTTP Body[2012-03-02T20:20:49.323+02:00][43gg84][info] Request cycle shutdown[2012-03-02T20:20:49.333+02:00][43gg84][info] Request cycle completed in 0.330 seconds.

 

幾乎每個 PHP 開發人員都會碰到這個 "headers sent" 的錯誤，在這裡堆疊追蹤資訊很小，當你使用 debug_backtrace() 方法可以指定不輸出對象資訊（傳遞 FALSE 做參數）。不過對象資訊提供了非常有用的資訊，但是它也會因此而產生了更多的噪音來幹撓你對日誌的閱讀。如果對象的調試正確，那其實就沒必要輸出對象資訊了。

要記錄的重要事件

並不是每個事件都有記錄的必要，我們將在下一小節裡描述這個問題，在這裡你需要瞭解的是日誌應該記錄什麼。

完成某項操作所需的時間

通過它可以跟蹤為什麼系統響應變慢或者太快

• 完成一個請求處理所需的時間，精確到毫秒
• 什麼時候接收到的請求
• 執行資料庫查詢的時間
• 從磁碟或者儲存系統擷取資料的時間
• 等等

異常和堆疊追蹤

異常資訊和堆疊追蹤資訊是很有價值的，但要處理好相當不易，特別是當你通過重新拋出異常來控制應用流程。在異常發生時記錄詳細的堆疊追蹤資訊對問題的確定是很有協助的。

會話

知道一個問題是由誰引起的非常重要，因此在日誌中使用工作階段識別項就變得必不可少。它可以簡單到是一個 IP 位址或者是一個跟複雜的 UUID，只要能區分不同的使用者就足夠。IP 位址有時候不能確認問題，因為很多公司都會使用同一個 IP 上互連網。

版本號碼

我經常碰到這樣的問題，一個 bug 在伺服器 A 上沒事，但在伺服器 B 上就經常出現，原因肯定就是版本的差別導致的，因此在日誌中你應該記錄當前軟體的版本號碼。

哪些內容無需記錄

日誌是用來標識問題的好方法，但不可過度使用，不要為了日誌而日誌。太多的日誌也會為尋找問題帶來困難，只應該繼續應用的關鍵資訊，當然這個“關鍵”很難去量化，你必須依照自身系統的情況來決定。

不要包含一些不相干的資訊，我看過很多系統把所有的環境變數都記錄到日誌中，包括整個請求的 dump 等等，這些東西沒有任何協助。

當然，哪些內容無需記錄你可以在監控過程中不斷的最佳化。

日誌記錄後該幹什嗎？

如果你還在閱讀此文，我非常感動 因為這篇文章可能真的很枯燥

但你記錄了很多日誌資訊，這些資訊包含大量有用的而且是更新的資訊，你必須監控它們，並從中找出存在的問題或者潛在的問題予以解決，那麼這些日誌就成了無用而且佔據著大量的系統資源。

異常處理

異常發生時必須詳細的進行記錄。在異常對象中建立一個日誌資訊在語義上是不正確的。一些邏輯和函數不應該放在異常內部去定義。但一個異常被重新拋出時，你應該記錄這個異常的詳細資料，包括：堆疊追蹤、錯誤碼和描述。

異常不應該改變應用的流程，只是用來指示問題的發生。

下面的代碼很顯然只有開發人員自己才能知道什麼情況是異常，什麼情況不是。下面這種情況我傾向於當沒找到使用者時不要拋出異常。

// ..// Fetching the user by the received ID.try {    $user = $service->findById( $id );} catch (SpecificServiceException $e) {    // Only the specific exception "SpecificServiceException" is being caught here.    // Other possible exceptions are caught later, so they are not logged here.    $this->getLogger()->logError( $e->getMessage() );}// Sorry, no data foundif ( ! $user instanceof User) {    return false;}// ..

 

處理 PHP 錯誤

但發生什麼問題時，PHP 會報錯，從 E_FATAL 到 E_STRICT，或者是使用者自訂的 E_USER_*. 你也可以通過自訂錯誤處理起來捕獲這些錯誤，例如在 php.ini 中通過 error_log = syslog 來將日誌寫到 syslog 中。

在所有環境中，除了開發環境，display_errors 和相關的設定都應該關閉，而在開發環境中必須開啟，error_reporting 應該設定為包含所有項。

貼士: 在 PHP 運行環境之外配置 PHP 的錯誤報表時，例如 Apache或者是SHELL指令碼，應使用整數值，這在PHP文檔中是沒有說明的，例如 error_reporting 設定為 -1 標識 E_ALL。

處理 E_STRICT 和 E_DEPRECATED

在 PHP 中有很多記錄層級，在開發過程中 E_STRICT 和 E_DEPRECATED 很重要，但沒有任何理由在產品環境中記錄這個資訊。

最後一點是應該在開發過程中解決所有 E_STRICT violation 的問題。

處理 E_NOTICE

Notices 相當於 PHP 的 Achilles' heel (不知道該怎麼翻譯). 它們並不被記錄，但能指示應用程式的健康狀態。如果你收到一個 notice 資訊，說明開發過程並不順利，可能會有不少潛在問題。你應該重視 E_NOTICE ，把它們當成是錯誤來對待，是需要修複的問題。

處理 @ 操作符

錯誤控制操作符 ("@") 是不推薦使用的，我經常看到很多偷懶的開發人員使用它，強烈建議不要使用，除非你真的需要。

不同的訊息層級以及什麼時候該用

如果你看 Zend Framework 是，你會注意到有 8 個錯誤層級，從 0 ~ 7，0 是最進階別。我個人覺得下面5種就足夠了：

常量名	描述說明
EMERG	災難 Emergency
ERR	錯誤 Error
WARN	警告 Warnings
INFO	基本資料 Informational
DEBUG	調試資訊 Debug

Emergency

但災難發生，系統完全停用時候，應該使用 EMERG 常量，要求維護人員立即處理。

例如：

• 後端伺服器不可訪問
• 資料庫掛了，無法訪問

 

Error

當碰到一些例如資料丟失，請求未處理完成等相關嚴重錯誤時使用，要求重視並應該採取行動。

例如：

• 請求未完成，而且沒法恢複
• 請求完成，資料丟失
• 某些情況下儲存資料失敗
• 接收到無效的資料
• 逾時或者回應時間太長
• 處理異常
• 安全相關問題

 

Warnings

但系統有些警告資訊需要注意時使用 WARN 常量，它表示某些比較奇怪的問題，這些問題應該在下一個版本中解決，系統運行還是正常無誤的，不需要立即採取行動。

例如：

• 接收不到資料，或者計劃外的資料
• 處理過程返回的狀態未定義，但無誤
• E-mails 延遲，但仍可送達
• 回應時間比較長，但不會太嚴重
• 其他非錯誤問題

 

Informational

應用程式中一些跟錯誤和警告無關的資訊記錄應使用 INFO 常量。

例如：

• 事務啟動，事務結束
• 發送某個 email 到某個地址
• 接收到來自 127.0.0.2 的 PUT 類型的 HTTP 要求
• 擷取ID為42的使用者詳細資料

 

Debug

調試資訊，僅僅用於跟蹤應用運行狀態。

例如：

• 使用 Mailer 適配器的參數值
• 請求參數名和值
• 資料庫查詢執行了多長時間以及返回多少條記錄
• 堆疊追蹤

 

聰明的日誌實現

前面我們提到，不應該在產品環境中啟用調試資訊，因為會讓系統佔用更多的資源。

日誌記錄應該使用如下偽碼的做法：

// If we have errors, include debug events in our logs. Else don't include them.if ($errorEventCount > 0) {    $allEvents = array_merge(        $criticalEvents, $errorEvents, $warningEvents, $infoEvents, $debugEvents    );} else {    $allEvents = array_merge(        $criticalEvents, $errorEvents, $warningEvents, $infoEvents    );}

 

結論

在完美世界中，日誌是不需要的，但現實不存在完美。儘管記錄日誌很簡單，但你應該謹慎處之，讓下一個開發人員能非常輕鬆的就理解日誌具體的意思。

最後非常感謝您閱讀這篇羅裡羅嗦的文章！

英文原文，OSCHINA 原創翻譯

紅薯註：在翻譯這篇文章時，裡面有不少小節我並沒有領會其中具體的意思，特別是 PHP 相關的，請大家見諒，如果有實在看不懂的可以參考英文原文。