不要踏到 Node.js 的黑洞陷阱 👉🕳 😵

Will Wang 王興謙
May 12 · 8 min read
精確的說是一個 nodemon 的陷阱,讓我 debug 到快崩潰,而且我發現不少人都有碰到。如果你有在用 nodemon,也許讀過這篇可以節省你很多小時。
(網路看到的圖 lol … 實際上遠不只 5 hours)

(註: 是一個知名的實用工具,會持續 monitor 你在開發 Node.js 時的 code,一有改動就自動重跑 node。)

我最近在開發一個 service,會用 Azure Service BusTopics ( 服務) 來傳遞 message:

  • 收送兩端都是用 Node.js 寫的
  • 收端有一個 while(1) loop 不斷收 message,收到後會 call foo() function 做事。

這裡是收端 code 的骨架,有需要的話可以參考:


一開始都很好,後來我開始碰到第一層問題:

收端「有時候」完全收不到 message (或只收到少數幾個)

於是我做這些事:

  1. 一直檢查 send 的 status code (always 成功)
  2. 檢查 azure () 有沒有收到 (時有時無)
  3. 研究 azure 的 ,包括故意讓 message body 不一樣 (沒用)
  4. 研究 rule
  5. 換 pub/sub topic name (沒用)
  6. 某些 string 單引號雙引號互換 ……. (ok 爛透了)
  7. 測試 peek lock (沒用)
  8. 測試最一開始有成功過的官方 example code
  9. 調整收訊息的 function 的 timeout (沒用)
  10. 乾脆把 azure service bus topics 降級:改用為比較單純的 azure service bus queue (還是有問題)
  11. …我覺得沒招了,只好一度暴力改成每次都送 50 個一樣的 message 到 Azure,總有一些會成功 …. (餵公子吃餅 🍪)

然後我發現問題的深一層:

雖然沒看到「收到 message 時會印的 console.log」,但其實 foo() 一直有被觸發(call)到。也就是說,其實有收到 message。

我發現並且證實的方法是,在一進入 foo() 時,就在 file system touch 一個 random 名字的 file,而我發現這些 file 一直狂噴出來 🚀 ,如下圖:

(我用 shell command `watch ls` 來觀測噴出來的檔案。實際上可以瘋狂噴出更多 🚀🚀🚀。)

所以我開始懷疑:我在 foo() 裡用的 module 是不是用錯了 (process detach, fork, wait child process 這類問題)

我也懷疑,是不是用錯 javascript 的 async/await 了 (還,感謝 community 😅):

  1. 懷疑await 會不會讓出去給別的 function 跑之後,那個 function 因某種原因會接不到 stdout?也就是我懷疑 foo 變成某種在背景跑但是 foo 內的 console.log 不會印出來,所以會以為沒跑到
  2. 懷疑:如果 function bar() 裡有個 while (1), 而當 while 裡在 await 某個 function 時, 有可能會回到 bar() 嗎?也就是跑出 while 了?

這裡也做了很多嘗試,包括反覆修改 async 邏輯,但還是一直都找不出問題。

還是懷疑人生好了…

然後,我發現為什麼了:

(黑洞:滿滿滿滿滿滿滿滿滿滿滿滿滿的 nodemon,不只一頁)

htop 裡,看到滿滿滿滿的 nodemon,不知道有幾個同時在跑 (而且都沒有接到 stdout) 😱😱😱

也就是說:

  1. 送端一送出 message,收端就有大量在背景偷跑的 nodemon 會瞬間收走大部份或是全部的 message
  2. 而且,大量nodemon收到 message 後就會各自開始瘋狂跑 foo(),跑到 CPU, GPU 跟 RAM 都耗盡,可以持續數十分鐘

所以我開始在想:nodemonNode.js 是不是在背景幫忙多開 process,因為 pm2 有這類行為。找了一些關鍵字,像是 nodejs nodemon pm2 default background process number 這些去排列組合,不過看不太出來問題所在。

結果後來找到一個很關鍵的 nodemon issue:

重點如下:

  1. 多名 nodemon user 都有發現 child process 被留在背景繼續跑(登愣!)
  2. 直接用 Ctrl + c (送出 SIGINT) 來結束 nodemon 不一定有用,除非在 nodemon.json 或 code 裡用 process.on() 明確處理 SIGINT/SIGHUP/SIGTERM 這些 signal,不過有人用了沒效果
  3. 有人 () 提出 root cause 是因為 nodemon 用了 Node.js 的 child_process.spawn 來建 child process,而不是用 child_process.fork,所以 kill 了 parent 不會 kill children.
    (. In this case, killing the parent does not kill its children.)
  4. nodemon 作者 () 回應說,因為他需要 spawn 提供的 IPC 功能,而 fork 沒有
  5. 討論到一半,有人就先把他 project 用的 nodemon 幹(換)掉了…XD (改用 babel-watch )
  6. 後來作者還是接受了修改的 PR (可以參考 nodemon 的 commit 62a361c, 在 2017/12/13, 重點 diff 見下圖)
commit 62a361c: “fix: use fork child node processes”

可是瑞凡,到了 2018 年底了還是不斷有人回報類似問題,噴到作者說請大家另外開 issue …

問題查到這裡,我突然想到一句之前引起討論的話:

…..XDDDD ()

回頭是岸,我目前並沒有打算再花時間挖這個問題,如果有人更了解這個問題,歡迎留言指導一下 😅 ( nodemon 有提到一些 signal 處理,也許是線索)

到此,我的個人結論:

我不敢用 nodemon 了

Note:

  1. 我用的 nodemon 版本是 1.18.10
  2. 我只有把 nodemon 用在 dev 環境
  3. 也有可能根本是我自己使用方法錯誤
  4. 後來因為這個 issue 還有其他原因,我用 python 重寫了這個 service。如果還是有 nodemon 這種需求,建議可以試著確認更深的 root cause。另外,還可以比較看看 pm2, forever, node-supervisor, node-dev, babel-watch。走刻苦手工路線的話也可以用 watchdog () 自己兜 …

最後,附上一張直接用 node 跑的「乾淨」 htop 圖,供參考:

(正在跑的 node 跟 node 自己生出來的 thread.)

總結一下過程

1. 用了 Azure Pub/Sub(還有 Queue),本來沒問題,但後來會一直收不到 message
2. 發現其實有收到 message,但是印不出 log
3. 發現 htop 裡有滿滿滿滿 nodemon 被留在背景跑
4. 現在的 nodemon 似乎還是會有這現象
5. 我逃了

如果有寫錯或是需要更新的,歡迎在留言提醒我~ 😃

非常感謝 幾位好友幫忙 review 了這篇文章 (A-Z):黃焌華 / Clyde Wu / Fischer Liu / gasolin / John Hu / kcliu / Luke Chang / Paul Yang / Ricky Chien / Sean Lee / Yu-Jen Chang

一些關於我的資訊:

Thanks to Clyde Wu.

Will Wang 王興謙

Written by

Software developer @Mozilla, Linker Networks。ex-有物報告 Technical Writer。我熱愛關於軟體開發的任何事情,理想是開發出讓社會及全人類過得更好的軟體。