Node程序debug小記

有時候，所見並非所得，有些包，你須要去翻他的源碼才知道爲何會這樣。

背景

今天調試一個程序，用到了一個好久以前的NPM包，名爲formstream，用來將form表單數據轉換爲流的形式進行接口調用時的數據傳遞。

這是一個幾年前的項目，因此使用的是Generator+co實現的異步流程。

其中有這樣一個功能，從某處獲取一些圖片URL，並將URL以及一些其餘的常規參數組裝到一塊兒，調用另外的一個服務，將數據發送過去。

大體是這樣的代碼：

const co         = require('co')
const moment     = require('moment')
const urllib     = require('urllib')
const Formstream = require('formstream')

function * main () {
  const imageUrlList = [
    'img1',
    'img2',
    'img3',
  ]

  // 實例化 form 表單對象
  const form = new Formstream()

  // 常規參數
  form.field('timestamp', moment().unix())

  // 將圖片 URL 拼接到 form 表單中
  imageUrlList.forEach(imgUrl => {
    form.field('image', imgUrl)
  })

  const options = {
    method: 'POST',
    // 生成對應的 headers 參數
    headers: form.headers(),
    // 告訴 urllib，咱們經過流的方式進行傳遞數據，並指定流對象
    stream: form
  }

  // 發送請求
  const result = yield urllib.request(url, options)

  // 輸出結果
  console.log(result)
}

co(main)
複製代碼

也算是一個比較清晰的邏輯，這樣的代碼也正常運行了一段時間。

若是沒有什麼意外，這段代碼可能還會在這裏安靜的躺不少年。
可是，現實老是殘酷的，由於一些不可抗拒因素，必需要去調整這個邏輯。
以前調用接口傳遞的是圖片URL地址，如今要改成直接上傳二進制數據。

因此需求很簡單，就是將以前的URL下載，拿到buffer，而後將buffer傳到formstream實例中便可。
大體是這樣的操做：

- imageUrlList.forEach(imgUrl => {
- form.field('image', imgUrl)
- })

+ let imageUrlResults = yield Promise.all(imageUrlList.map(imgUrl => 
+ urllib.request(imgUrl)
+ ))
+ 
+ imageUrlResults = imageUrlResults.filter(img => img && img.status === 200).map(img => img.data)
+
+ imageUrlResults.forEach(imgBuffer => {
+ form.buffer('image', imgBuffer)
+ })
複製代碼

下載圖片 -> 過濾空數據 -> 拼接到form中去，代碼看起來毫無問題。

不過在執行的時候，卻出現了一個使人頭大的問題。
最終調用yield urllib.request(url, options)的時候，提示接口超時了，起初還覺得是網絡問題，因而多執行了幾回，發現仍是這樣，開始意識到，應該是剛纔的代碼改動引起的bug。

開始 debug

定位引起 bug 的代碼

我習慣的調試方式，是先用最原始的方式，眼，看有哪些代碼修改。
由於代碼都有版本控制，因此大多數編輯器均可以很直觀的看到有什麼代碼修改，即便編輯器中沒法看到，也能夠在命令行中經過git diff來查看修改。

此次的改動就是新增的一個批量下載邏輯，以及URL改成Buffer。
先用最簡單粗暴的方式來確認是這些代碼影響的，註釋掉新增的代碼，還原老代碼。
結果果真是能夠正常執行了，那麼咱們就能夠判定bug就是由這些代碼所致使的。

逐步還原錯誤代碼

上邊那個方式只是一個rollback，幫助肯定了大體的範圍。
接下來就是要縮小錯誤代碼的範圍。
通常代碼改動大的時候，會有多個函數的聲明，那麼就按照順序逐個解開註釋，來查看運行的效果。
此次由於是比較小的邏輯調整，因此直接在一個函數中實現。
那麼很簡單的，在保證程序正常運行的前提下，咱們就按照代碼語句一行行的釋放。

很幸運，在第一行代碼的註釋被打開後就復現了bug，也就是那一行yield Promsie.all(XXX)。
可是這個語句實際上也能夠繼續進行拆分，爲了排除是urllib的問題，我將該行代碼換爲一個最基礎的Promise對象：yield Promise.resolve(1)。
結果令我很吃驚，這麼一個簡單的Promise執行也會致使下邊的請求超時。

當前的部分代碼狀態：

const form = new Formstream()

form.field('timestamp', moment().unix())

yield Promise.resolve(1)

const options = {
 method: 'POST',
 headers: form.headers(),
 stream: form
}

// 超時
const result = yield urllib.request(url, options)
複製代碼

再縮小了範圍之後，進一步進行排查。
目前所剩下的代碼已經不錯了，惟一可能會致使請求超時的狀況，可能就是發請求時的那些options參數了。
因此將options中的headers和stream都註釋掉，再次執行程序後，果真能夠正常訪問接口（雖然說會提示出錯，由於必選的參數沒有傳遞）。

那麼目前咱們能夠獲得一個結論：formstream實例+Promise調用會致使這個問題。

冷靜、懺悔

接下來要作的就是深呼吸，冷靜，讓心率恢復平穩再進行下一步的工做。
在我獲得上邊的結論以後，第一時間是崩潰的，由於致使這個bug的環境仍是有些複雜的，涉及到了三個第三方包，co、formstream和urllib。
而直觀的去看代碼，本身寫的邏輯實際上是不多的，因此不免會在心中開始抱怨，以爲是第三方包在搞我。
但這時候要切記「程序員修煉之道」中的一句話：

"Select" Isn't Broken
「Select」 沒有問題

因此必定要在心裏告訴本身：「你所用的包都是通過了N久時間的洗禮，必定是一個很穩健的包，這個bug必定是你的問題」。

分析問題

當咱們達成這個共識之後，就要開始進行問題的分析了。
首先你要了解你所使用的這幾個包的做用是什麼，若是能知道他們是怎麼實現的那就更好了。

對於co，就是一個利用yield語法特性將Promise轉換爲更直觀的寫法罷了，沒有什麼額外的邏輯。
而urllib也會在每次調用request時建立一個新的client（剛開始有想過會不會是由於屢次調用urllib致使的，不過用簡單的Promise.resolve代替以後，這個念頭也打消了）

那麼矛頭就指向了formstream，如今要進一步的瞭解它，不過經過官方文檔進行查閱，並不能獲得太多的有效信息。

源碼閱讀

源碼地址

因此爲了解決問題，咱們須要去閱讀它的源碼，從你在代碼中調用的那些 API 入手：

1. 構造函數
2. field
3. headers

構造函數養分並很少，就是一些簡單的屬性定義，而且看到了它繼承自Stream，這也是爲何可以在urllib的options中直接填寫它的緣由，由於是一個Stream的子類。

util.inherits(FormStream, Stream);
複製代碼

而後就要看field函數的實現了。

FormStream.prototype.field = function (name, value) {
  if (!Buffer.isBuffer(value)) {
    // field(String, Number)
    // https://github.com/qiniu/nodejs-sdk/issues/123
    if (typeof value === 'number') {
      value = String(value);
    }
    value = new Buffer(value);
  }
  return this.buffer(name, value);
};
複製代碼

從代碼的實現看，field也只是一個Buffer的封裝處理，最終仍是調用了.buffer函數。
那麼咱們就順藤摸瓜，繼續查看buffer函數的實現。

FormStream.prototype.buffer = function (name, buffer, filename, mimeType) {
  if (filename && !mimeType) {
    mimeType = mime.lookup(filename);
  }

  var disposition = { name: name };
  if (filename) {
    disposition.filename = filename;
  }

  var leading = this._leading(disposition, mimeType);

  this._buffers.push([leading, buffer]);

  // plus buffer length to total content-length
  this._contentLength += leading.length;
  this._contentLength += buffer.length;
  this._contentLength += NEW_LINE_BUFFER.length;

  process.nextTick(this.resume.bind(this));

  return this;
};
複製代碼

代碼不算少，不過大多都不是此次須要關心的，大體的邏輯就是將Buffer拼接到數組中去暫存，在最後結尾的地方，發現了這樣的一句代碼：process.nextTick(this.resume.bind(this))。
頓時眼前一亮，重點的是那個process.nextTick，你們應該都知道，這個是在Node中實現微任務的其中一個方式，而另外一種實現微任務的方式，就是用Promise。

修改代碼驗證猜測

拿到這樣的結果之後，我以爲彷彿找到了突破口，因而嘗試性的將前邊的代碼改成這樣：

const form = new Formstream()

form.field('timestamp', moment().unix())

yield Promise.resolve(1)

const options = {
 method: 'POST',
 headers: form.headers(),
 stream: form
}

process.nextTick(() => {
  urllib.request(url, options)
})
複製代碼

發現，果真超時了。

從這裏就能大體推斷出問題的緣由了。
由於看代碼能夠很清晰的看出，field函數在調用後，會註冊一個微任務，而咱們使用的yield或者process.nextTick也會註冊一個微任務，可是field的先註冊，因此它的必定會先執行。
那麼很顯而易見，問題就出如今這個resume函數中，由於resume的執行早於urllib.request，因此致使其超時。
這時候也能夠同步的想一下形成request超時的狀況會是什麼。
只有一種可能性是比較高的，由於咱們使用的是stream，而這個流的讀取是須要事件來觸發的，stream.on('data')、stream.on('end')，那麼超時頗有多是由於程序沒有正確接收到stream的事件致使的。

固然了，「程序員修煉之道」還講過：

Don't Assume it - Prove It
不要假定，要證實

因此爲了證明猜想，須要繼續閱讀formstream的源碼，查看resume函數究竟作了什麼。
resume函數是一個很簡單的一次性函數，在第一次被觸發時調用drain函數。

FormStream.prototype.resume = function () {
  this.paused = false;

  if (!this._draining) {
    this._draining = true;
    this.drain();
  }

  return this;
};
複製代碼

那麼繼續查看drain函數作的是什麼事情。
由於上述使用的是field，而非stream，因此在獲取item的時候，確定爲空，那麼這就意味着會繼續調用_emitEnd函數。
而_emitEnd函數只有簡單的兩行代碼emit('data')和emit('end')。

FormStream.prototype.drain = function () {
  console.log('start drain')
  this._emitBuffers();

  var item = this._streams.shift();
  if (item) {
    this._emitStream(item);
  } else {
    this._emitEnd();
  }

  return this;
};

FormStream.prototype._emitEnd = function () {
  this.emit('data', this._endData);
  this.emit('end');
};
複製代碼

看到這兩行代碼，終於能夠證明了咱們的猜測，由於stream是一個流，接收流的數據須要經過事件傳遞，而emit就是觸發事件所使用的函數。
這也就意味着，resume函數的執行，就表明着stream發送數據的動做，在發送完畢數據後，會執行end，也就是關閉流的操做。

得出結論

到了這裏，終於能夠得出完整的結論：

formstream在調用field之類的函數後會註冊一個微任務
微任務執行時會使用流開始發送數據，數據發送完畢後關閉流
由於在調用urllib以前還註冊了一個微任務，致使urllib.request其實是在這個微任務內部執行的
也就是說在request執行的時候，流已經關閉了，一直拿不到數據，因此就拋出異常，提示接口超時。

那麼根據以上的結論，如今就知道該如何修改對應的代碼。
在調用field方法以前進行下載圖片資源，保證formstream.field與urllib.request之間的代碼都是同步的。

let imageUrlResults = yield Promise.all(imageUrlList.map(imgUrl => 
  urllib.request(imgUrl)
))

const form = new Formstream()

form.field('timestamp', moment().unix())

imageUrlResults = imageUrlResults.filter(img => img && img.status === 200).map(img => img.data)
imageUrlResults.forEach(imgBuffer => {
  form.buffer('image', imgBuffer)
})

const options = {
 method: 'POST',
 headers: form.headers(),
 stream: form
}

yield urllib.request(url, options)
複製代碼

小結

這並非一個有各類高大上名字、方法論的一個調試方式。
不過我我的以爲，它是一個很是有效的方式，並且是一個收穫會很是大的調試方式。
由於在調試的過程當中，你會去認真的瞭解你所使用的工具到底是如何實現的，他們是否真的就像文檔中所描述的那樣運行。

關於上邊這點，順便吐槽一下這個包：thenify-all。
是一個不錯的包，用來將普通的Error-first-callback函數轉換爲thenalbe函數，可是在涉及到callback會接收多個返回值的時候，該包會將全部的返回值拼接爲一個數組並放入resolve中。
實際上這是很使人困惑的一點，由於根據callback返回參數的數量來區別編寫代碼。
並且thenable約定的規則就是返回callback中的除了error之外的第一個參數。

可是這個在文檔中並無體現，而是簡單的使用readFile來舉例，很容易對使用者產生誤導。
一個最近的例子，就是我使用util.promisify來替換掉thenify-all的時候，發現以前的mysql.query調用莫名其妙的報錯了。

// 以前的寫法
const [res] = await mysqlClient.query(`SELECT XXX`)

// 如今的寫法
const res = await mysqlClient.query(`SELECT XXX`)
複製代碼

這是由於在mysql文檔中明肯定義了，SELECT語句之類的會傳遞兩個參數，第一個是查詢的結果集，而第二個是字段的描述信息。
因此thenify-all就將兩個參數拼接爲了數組進行resolve，而在切換到了官方的實現後，就形成了使用數組解構拿到的只是結果集中的第一條數據。

最後，再簡單的總結一下套路，但願可以幫到其餘人：

1. 屏蔽異常代碼，肯定穩定復現（還原修改）
2. 逐步釋放，縮小範圍（一行行的刪除註釋）
3. 肯定問題，利用基礎demo來屏蔽噪音（相似前邊的yield Promise.resolve(1)操做）
4. 分析緣由，看文檔，啃源碼（瞭解這些代碼爲何會出錯）
5. 經過簡單的實驗來驗證猜測（這時候你就能知道怎樣才能避免相似的錯誤）