Node程式debug小記

賈順名發表於2019-02-16

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

背景

今天除錯一個程式，用到了一個很久之前的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. 通過簡單的實驗來驗證猜想（這時候你就能知道怎樣才能避免類似的錯誤）

相關文章