Node.js 應用日誌切割原理與踩坑實踐

時間 2020-05-10

標籤 node.js node 應用日誌切割原理實踐欄目 Node.js 简体版

原文原文鏈接

圖片來源： https://medium.com/encored-te...
本文做者：夏銀竹javascript

引子

2019 年初的時候，咱們業務組上線了一個新的 Node.js 應用，主要提供C端的 API 服務。隨着應用流量的逐漸增長，線上監控平臺會偶發性報警，提示磁盤 disk_io 平均等待時間超出 1000ms，隨後觀察發現磁盤 IO 每秒寫字節量忽然飆高，但很快又降低。前端

具體的監控圖表如上所示，線上 Node.js 應用向磁盤寫入數據的惟一場景就是打印日誌，經過iotop、ps 等命令也驗證了該異常正是因爲 Node.js 的日誌切割進程致使的。java

但是爲何日誌切割會引發這麼詭異的 IO 問題呢？在揭開謎底以前，咱們先聊一聊 Node.js 應用日誌切割的原理。node

日誌切割原理

爲何須要日誌切割

日誌打印是 Node.js 工程服務化過程當中一個必不可少的環節。日誌文件中包含了系統運行過程當中的關鍵信息，經常使用於故障診斷和系統的性能分析。git

在日誌打印的過程當中一般會遇到兩個問題：github

隨着時間的積累，日誌文件大小會逐漸增加，系統磁盤的空間會被消耗得愈來愈多，將面臨着日誌寫入失敗、服務異常的問題。
服務的日誌默認存儲在單個文件中，自定義查看歷史某個時間段的日誌將會變得比較困難，指望日誌文件可以按照必定的規則切割，以便於排序和篩選。

因此，在生產環境中一般會採用日誌切割來解決上述的問題。日誌切割能夠限制日誌文件個數，刪除舊的日誌文件，並建立新的日誌文件，起到「轉儲做用」。架構

實現機制

不一樣的日誌切割組件會採用不一樣的實現機制，常見的有如下兩種：app

copytruncate 模式：框架
1. copy 當前日誌文件，重命名爲新的日誌文件，這樣進程仍是往老的日誌文件寫入。
2. 對老的日誌文件進行 truncate 清空，這樣就完成了一第二天志切割。
sign 通知模式：async
1. 首先重命名當前進程正在輸出的日誌文件名稱。由於日誌文件是用 inode 來在磁盤上標識，更改日誌文件名稱並不會影響 inode 號，進程依舊會往修改了名稱的日誌文件內輸出日誌。
2. 建立新的日誌文件，文件名稱和老的日誌文件名稱保持一致。由於是新建的文件，inode 號不同。此時進程日誌仍是依舊輸出到老的被重命名了的日誌文件裏面。
3. 對進程發起信號通知，讓其重載日誌的配置文件，實現平滑重啓，後續的日誌就會寫入到新建的日誌文件裏。

日誌切割組件通常都支持可配置日誌切割頻率，也有兩種方式：

定時切割：進程啓動一個定時任務，到設定時間後切割日誌文件。
按大小切割：進程定時監控日誌文件的大小，若文件超出設定的最大值時進行切割。

Node.js 應用日誌切割

對於前端 Node.js 應用來講，根據項目的框架和部署架構，可選擇不一樣的日誌切割方案，例如：

基於 pm2 部署的 Node.js 應用，可採用 pm2-logrotate 實現日誌切割。
基於 Egg.js 框架的 Node.js 應用，可採用 egg-logrotator 實現日誌切割。

下面咱們詳細介紹一下這兩種日誌切割方案的實現原理。

pm2-logrotate

實現機制

pm2-logrotate 是 pm2 擴展的日誌管理插件，適用於 pm2 部署的 Node.js 應用，同時支持定時切割和按大小切割。

可經過以下的命令來設置一些配置參數：

pm2 set pm2-logrotate:<param> <value>

其中的關鍵配置項以下：

max_size
日誌文件的最大致積，默認值爲 10 1024 1024
retain
切割出的日誌文件最大份數，默認值爲 30
dateFormat
日期格式，基於該日期名生成切割出的日誌文件名稱，默認值爲 YYYY-MM-DD_HH-mm-ss
workerInterval
按大小切割時，文件掃描的間隔時間（s），默認值爲 30
rotateInterval
定時切割的時間間隔（支持cron表達式），默認值爲 0 0 *

對於pm2-logrotate 自己的實現機制，咱們探究源碼總結出了一些關鍵的步驟，具體如圖所示：

其中切割機制的核心源碼以下，從這裏咱們能夠看出 pm2-logrotate 採用了上文介紹的 copytruncate 模式。

// 日誌切割的具體過程
function proceed(file) {
  // 設置時間做爲新的日誌文件名
  var final_time = moment().format(DATE_FORMAT);
  var final_name = file.substr(0, file.length - 4) + '__' + final_time + '.log';

  // 建立 read/write streams，將日誌寫入到新的日誌文件中
  var readStream = fs.createReadStream(file);
  var writeStream = fs.createWriteStream(final_name, {'flags': 'w+'}); 
    
  readStream.pipe(writeStream);
  
  // 日誌寫入完畢後， 清空應用的日誌文件
  writeStream.on('finish', function() {
    readStream.close();
    writeStream.close();
    fs.truncate(file, function (err) {
      console.log('"' + final_name + '" has been created');
      if (typeof(RETAIN) === 'number') 
        delete_old(file);
    });
  });
}

IO 異常問題分析

從新回到本文開頭的線上問題，因爲咱們的 Node.js 應用是基於 pm2 實現進程管理，一樣也是基於 pm2-logrotate 來實現日誌切割。

在排查異常的時候，咱們發現了 pm2-logrotate 在實現上的兩個問題。

cluster 模式下重複切割日誌的問題

經過追溯源碼，咱們能夠肯定 pm2-logrotate 會對全部由 pm2 啓動的應用進行日誌切割。

pm2.list(function(err, apps) {
  apps.forEach(function(app) {
    proceed_app(app, false);
  });
});

可是，在 cluster 模式下，pm2 會啓動多個相同的 woker 實例，而日誌只會打印到同一份文件中。所以，當觸發日誌切割的條件時，多個 woker 實例會同時對日誌文件進行切割，形成 IO 讀寫繁忙。

同時， copytruncate 模式在日誌切割的時候會拷貝原來的日誌文件，也會形成系統磁盤使用空間突增。

這個問題在日誌文件體積大的時候尤其明顯，也是咱們 Node.js 應用線上 IO 異常的主因。

爲了解決 cluster 模式下重複切割日誌的問題，須要對多個 worker 實例進行去重判斷，只容許一個實例進行日誌切割的操做。具體的判斷邏輯可分紅兩步：

判斷該實例是否爲 cluster 模式下的實例。pm2 給每一個應用實例提供了環境變量 pm2_env 來查看運行的狀態。 app.pm2_env.instances > 1 則代表有多個相同的實例，可斷定爲 cluster 模式。
判斷是否有實例已經作了日誌切割。多個 worker 實例的共同點是 app.name 應用名相同。所以，每第二天志切割的時候新建一個 map 映射表，key 爲 app.name ，只有當映射表中沒有查詢到 app.name 的時候，纔會進行日誌切割。

代碼部分大體以下所示：

pm2.list(function(err, apps) {
  ...
  var appMap = {};
  apps.forEach(function(app) {
    // cluster模式下的去重判斷
    if(app.pm2_env.instances > 1 && appMap[app.name]) return;
    appMap[app.name] = app;
    
        // 開始日誌切割
    proceed_app(app, false);
});

以上去重判斷的邏輯已經提交 PR 並被 merged 。該問題已在 pm2-logrotate v2.7.0 的版本修復。

日誌丟失問題

pm2-logrotate 進行日誌切割時，新的日誌文件名是根據 dateFormat 參數格式化生成的，源碼以下所示：

var DATE_FORMAT = conf.dateFormat || 'YYYY-MM-DD_HH-mm-ss';
var final_time = moment().format(DATE_FORMAT);
var final_name = file.substr(0, file.length - 4) + '__' + final_time + '.log';

該參數的默認值 YYYY-MM-DD_HH-mm-ss，能夠精確到秒級別。在實際生產環境，爲了便於檢索和查看日誌，文件的命名每每會按照按天/小時的維度進行命名。

可是若是 DATE_FORMAT 的格式爲 YYYY-MM-DD ，會存在這麼一個坑：當一天中應用日誌體積屢次超出設置的 max_size 後，會出現屢次切割的操做，可是每次切割生成的新日誌文件名倒是相同的。

在已有切割日誌的狀況下， pm2-logrotate 再次切割時不會判斷新的日誌文件是否已經存在，而是直接用新切割出來的日誌覆蓋了以前的日誌，從而會致使日誌丟失。

// 若是final_name對應的文件不存在則建立，存在則總體內容覆蓋
var writeStream = fs.createWriteStream(final_name, {'flags': 'w+'});

針對該問題的解決方案，一方面能夠經過設置 dateFormat 精確到秒級來避免；另外一方面，須要評估日誌文件的大小，合理設置 max_size 參數，避免頻繁觸發日誌切割。

egg-logrotator

實現機制

egg-logrotator 是 Egg.js 框架擴展的日誌切割插件。相較於 pm2-logrotate ，其配置更加靈活，同時支持按天切割、按小時切割和按大小切割。關鍵配置項以下：

filesRotateByHour
須要按小時切割的文件列表，默認值爲 [ ]
hourDelimiter
按小時切割的文件，小時部分的分隔符號，默認值爲 '-'
filesRotateBySize
須要按大小切割的文件列表，默認值爲 [ ]
maxFileSize
日誌文件的最大致積，默認值爲 50 1024 1024
maxFiles
按大小切割時，文件最大切割的份數，默認值爲 10
rotateDuration
按大小切割時，文件掃描的間隔時間，默認值爲 60000
maxDays
日誌保留的最久天數，默認值爲 31

具體切割的實現原理如圖所示：

其中的核心源碼以下，相較於 pm2-logrotate ，從這裏咱們能夠看出 egg-logrotator 則採用了另一種 sign 通知模式。

// rotate 日誌切割源碼
async rotate() {
      // 獲取須要切割的日誌文件列表
    const files = await this.getRotateFiles();
    const rotatedFile = [];
    for (const file of files.values()) {
      try {
        // 重命名日誌文件
        await renameOrDelete(file.srcPath, file.targetPath);
        rotatedFile.push(`${file.srcPath} -> ${file.targetPath}`);
      } catch (err) {
      }
    }

    if (rotatedFile.length) {
      // reload 從新加載日誌文件
      this.logger.info('[egg-logrotator] broadcast log-reload');
      this.app.messenger.sendToApp('log-reload');
      this.app.messenger.sendToAgent('log-reload');
    }
  }
}

// reload從新加載日誌文件
reload() {
  this._closeStream();   // 結束當前日誌文件流
  this._stream = this._createStream(); // 建立一個新的寫日誌文件流
}

優點

就實現方式而言，copytruncate 模式較簡單，sign 通知模式則較爲複雜，須要有一套完整的通知重啓機制。

可是相較於基於 copytruncate 模式實現的pm2-logrotate，基於 sign 通知模式實現的 egg-logrotator 具備兩點明顯的優點：

copytruncate 模式在日誌切割的過程當中須要拷貝原來的日誌文件，若是日誌文件過大，系統可用空間會忽然爆增。sign 通知模式則無需拷貝原來的日誌文件。
對於按大小切割的場景， egg-logrotator 充分考慮了切割出的日誌文件命名問題。新的日誌文件會被命名爲 ${final_name}.1 。當已有切割文件時，會將原文件自增1，如文件名後綴加1（ .log.1 -> .log.2 ），直到日誌文件數量達到 maxFiles 最大值後，纔會直接覆蓋最後一份 .log.${maxFiles}。這種實現方式可以最大程度上保證日誌的完整性。