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 入手：
建構函式營養並不多，就是一些簡單的屬性定義，並且看到了它繼承自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)操作） - 分析原因，看文件，啃原始碼（瞭解這些程式碼為什麼會出錯）
- 通過簡單的實驗來驗證猜想（這時候你就能知道怎樣才能避免類似的錯誤）