摘要：當前的部分代碼狀態超時再縮小了范圍以后，進一步進行排查。函數是一個很簡單的一次性函數，在第一次被觸發時調用函數。因為上述使用的是，而非，所以在獲取的時候，肯定為空，那么這就意味著會繼續調用函數。

有時候，所見并不是所得，有些包，你需要去翻他的源碼才知道為什么會這樣。

今天調試一個程序，用到了一個很久之前的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。

我習慣的調試方式，是先用最原始的方式，__眼__，看有哪些代碼修改。
因為代碼都有版本控制，所以大多數編輯器都可以很直觀的看到有什么代碼修改，即使編輯器中無法看到，也可以在命令行中通過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 入手：

構造函數

field

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，而在切換到了官方的實現后，就造成了使用數組解構拿到的只是結果集中的第一條數據。

最后，再簡單的總結一下套路，希望能夠幫到其他人：

屏蔽異常代碼，確定穩定復現（還原修改）

逐步釋放，縮小范圍（一行行的刪除注釋）

確定問題，利用基礎demo來屏蔽噪音（類似前邊的yield Promise.resolve(1)操作）

分析原因，看文檔，啃源碼（了解這些代碼為什么會出錯）

通過簡單的實驗來驗證猜想（這時候你就能知道怎樣才能避免類似的錯誤）