天天看點
傳回

Logging 日志記錄最佳實踐

介紹

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

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

不同的日志含義

日志 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)

這條日志中包含：

日期、時間，提供毫秒資訊和時區

會話辨別 43gg84，不同的用戶端會有不同的值

日志級别，在這裡是 info

日志詳情：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 做參數）。不過對象資訊提供了非常有用的資訊，但是它也會是以而生成了更多的噪音來幹撓你對日志的閱讀。如果對象的調試正确，那其實就沒必要輸出對象資訊了。

要記錄的重要事件

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

完成某項操作所需的時間

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

  1. 完成一個請求處理所需的時間，精确到毫秒
  2. 什麼時候接收到的請求
  3. 執行資料庫查詢的時間
  4. 從磁盤或者存儲系統擷取資料的時間
  5. 等等

異常和堆棧跟蹤

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

會話

知道一個問題是由誰引起的非常重要，是以在日志中使用會話辨別符就變得必不可少。它可以簡單到是一個 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 found
if ( ! $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
    );
}

結論

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

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

php 伺服器 前端 3g 堆棧
上一篇: html行高設定失效,科技常識：關于css中line-height(行高)設定無效的問題的解決方法...
下一篇: PAT_甲級_1138 Postorder Traversal (25point(s)) (C++)【樹的周遊/先序+中序->後序】

繼續閱讀